From bc8c001312ba87cb4069b5a1785bb8fef607f079 Mon Sep 17 00:00:00 2001

From: Thomas Haller <thaller@redhat.com>

Date: Wed, 7 Jun 2017 12:18:21 +0200

Subject: [PATCH 01/10] device: rework device's _NMLOG() logging macro

- if the interface-name is NULL, print [null], to distinguish

  it from (ifname).

- evaluate the ifname only once.

(cherry picked from commit f10b95880666fe611fb2d0c27d49bfe3988ec9ec)

(cherry picked from commit 60ce882419201f75ac762e559854c85926263fe1)

---

 src/devices/nm-device-logging.h | 22 ++++++++++++++++------

 1 file changed, 16 insertions(+), 6 deletions(-)

diff --git a/src/devices/nm-device-logging.h b/src/devices/nm-device-logging.h

index 419a4a5..5f95a91 100644

--- a/src/devices/nm-device-logging.h

+++ b/src/devices/nm-device-logging.h

@@ -34,11 +34,21 @@ _nm_device_log_self_to_device (t *self) \

 #undef  _NMLOG_ENABLED

 #define _NMLOG_ENABLED(level, domain) ( nm_logging_enabled ((level), (domain)) )

 #define _NMLOG(level, domain, ...) \

-    nm_log_obj ((level), (domain), \

-                (self) ? nm_device_get_iface (_nm_device_log_self_to_device (self)) : NULL, \

-                NULL, (self), "device", \

-                "(%s): " _NM_UTILS_MACRO_FIRST(__VA_ARGS__), \

-                (self) ? (nm_device_get_iface (_nm_device_log_self_to_device (self)) ?: "(null)") : "(none)" \

-                _NM_UTILS_MACRO_REST(__VA_ARGS__))

+	G_STMT_START { \

+		const NMLogLevel _level = (level); \

+		const NMLogDomain _domain = (domain); \

+		\

+		if (nm_logging_enabled (_level, _domain)) { \

+			typeof (*self) *const _self = (self); \

+			const char *const _ifname = _self ? nm_device_get_iface (_nm_device_log_self_to_device (_self)) : NULL; \

+			\

+			nm_log_obj (_level, _domain, \

+			            _ifname, NULL, \

+			            _self, "device", \

+			            "%s%s%s: " _NM_UTILS_MACRO_FIRST(__VA_ARGS__), \

+			            NM_PRINT_FMT_QUOTED (_ifname, "(", _ifname, ")", "[null]") \

+			            _NM_UTILS_MACRO_REST(__VA_ARGS__)); \

+		} \

+	} G_STMT_END

 #endif /* __NETWORKMANAGER_DEVICE_LOGGING_H__ */

-- 

2.9.4

From 5449347dcb049ed7f7d5a9ee022dcf2b2d676412 Mon Sep 17 00:00:00 2001

From: Thomas Haller <thaller@redhat.com>

Date: Wed, 7 Jun 2017 17:22:16 +0200

Subject: [PATCH 02/10] device: expose nm_device_state_to_str() function for

 NMDeviceState

(cherry picked from commit 4b15df26561d5cf3890c9f8e1ec0266547d1cb7a)

(cherry picked from commit e0b7a44062ac870dc884021704f915b21caeaa52)

---

 src/devices/nm-device.c | 28 ++++++++++++++--------------

 src/devices/nm-device.h |  3 +++

 2 files changed, 17 insertions(+), 14 deletions(-)

diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c

index 404dcf7..fdf88c9 100644

--- a/src/devices/nm-device.c

+++ b/src/devices/nm-device.c

@@ -557,8 +557,8 @@ NM_UTILS_LOOKUP_STR_DEFINE_STATIC (queued_state_to_string, NMDeviceState,

 	NM_UTILS_LOOKUP_STR_ITEM (NM_DEVICE_STATE_FAILED,       NM_PENDING_ACTIONPREFIX_QUEUED_STATE_CHANGE "failed"),

 );

-static const char *

-state_to_string (NMDeviceState state)

+const char *

+nm_device_state_to_str (NMDeviceState state)

 {

 	return queued_state_to_string (state) + NM_STRLEN (NM_PENDING_ACTIONPREFIX_QUEUED_STATE_CHANGE);

 }

@@ -3423,9 +3423,9 @@ slave_state_changed (NMDevice *slave,

 	_LOGD (LOGD_DEVICE, "slave %s state change %d (%s) -> %d (%s)",

 	       nm_device_get_iface (slave),

 	       slave_old_state,

-	       state_to_string (slave_old_state),

+	       nm_device_state_to_str (slave_old_state),

 	       slave_new_state,

-	       state_to_string (slave_new_state));

+	       nm_device_state_to_str (slave_new_state));

 	/* Don't try to enslave slaves until the master is ready */

 	if (priv->state < NM_DEVICE_STATE_CONFIG)

@@ -4434,7 +4434,7 @@ recheck_available (gpointer user_data)

 		_LOGD (LOGD_DEVICE, "is %savailable, %s %s",

 		       now_available ? "" : "not ",

 		       new_state == NM_DEVICE_STATE_UNAVAILABLE ? "no change required for" : "will transition to",

-		       state_to_string (new_state == NM_DEVICE_STATE_UNAVAILABLE ? state : new_state));

+		       nm_device_state_to_str (new_state == NM_DEVICE_STATE_UNAVAILABLE ? state : new_state));

 		priv->recheck_available.available_reason = NM_DEVICE_STATE_REASON_NONE;

 		priv->recheck_available.unavailable_reason = NM_DEVICE_STATE_REASON_NONE;

@@ -12536,8 +12536,8 @@ _set_state_full (NMDevice *self,

 	    && (   state != NM_DEVICE_STATE_UNAVAILABLE

 	        || !priv->firmware_missing)) {

 		_LOGD (LOGD_DEVICE, "state change: %s -> %s (reason '%s') [%d %d %d]%s",

-		       state_to_string (old_state),

-		       state_to_string (state),

+		       nm_device_state_to_str (old_state),

+		       nm_device_state_to_str (state),

 		       reason_to_string (reason),

 		       old_state,

 		       state,

@@ -12547,8 +12547,8 @@ _set_state_full (NMDevice *self,

 	}

 	_LOGI (LOGD_DEVICE, "state change: %s -> %s (reason '%s') [%d %d %d]",

-	       state_to_string (old_state),

-	       state_to_string (state),

+	       nm_device_state_to_str (old_state),

+	       nm_device_state_to_str (state),

 	       reason_to_string (reason),

 	       old_state,

 	       state,

@@ -12872,7 +12872,7 @@ queued_state_set (gpointer user_data)

 	nm_assert (priv->queued_state.id);

 	_LOGD (LOGD_DEVICE, "queue-state[%s, reason:%s, id:%u]: %s",

-	       state_to_string (priv->queued_state.state),

+	       nm_device_state_to_str (priv->queued_state.state),

 	       reason_to_string (priv->queued_state.reason),

 	       priv->queued_state.id,

 	       "change state");

@@ -12903,7 +12903,7 @@ nm_device_queue_state (NMDevice *self,

 	if (priv->queued_state.id && priv->queued_state.state == state) {

 		_LOGD (LOGD_DEVICE, "queue-state[%s, reason:%s, id:%u]: %s%s%s%s",

-		       state_to_string (priv->queued_state.state),

+		       nm_device_state_to_str (priv->queued_state.state),

 		       reason_to_string (priv->queued_state.reason),

 		       priv->queued_state.id,

 		       "ignore queuing same state change",

@@ -12919,7 +12919,7 @@ nm_device_queue_state (NMDevice *self,

 	/* We should only ever have one delayed state transition at a time */

 	if (priv->queued_state.id) {

 		_LOGW (LOGD_DEVICE, "queue-state[%s, reason:%s, id:%u]: %s",

-		       state_to_string (priv->queued_state.state),

+		       nm_device_state_to_str (priv->queued_state.state),

 		       reason_to_string (priv->queued_state.reason),

 		       priv->queued_state.id,

 		       "replace previously queued state change");

@@ -12932,7 +12932,7 @@ nm_device_queue_state (NMDevice *self,

 	priv->queued_state.id = g_idle_add (queued_state_set, self);

 	_LOGD (LOGD_DEVICE, "queue-state[%s, reason:%s, id:%u]: %s",

-	       state_to_string (state),

+	       nm_device_state_to_str (state),

 	       reason_to_string (reason),

 	       priv->queued_state.id,

 	       "queue state change");

@@ -12947,7 +12947,7 @@ queued_state_clear (NMDevice *self)

 		return;

 	_LOGD (LOGD_DEVICE, "queue-state[%s, reason:%s, id:%u]: %s",

-	       state_to_string (priv->queued_state.state),

+	       nm_device_state_to_str (priv->queued_state.state),

 	       reason_to_string (priv->queued_state.reason),

 	       priv->queued_state.id,

 	       "clear queued state change");

diff --git a/src/devices/nm-device.h b/src/devices/nm-device.h

index 01e3938..edbb0aa 100644

--- a/src/devices/nm-device.h

+++ b/src/devices/nm-device.h

@@ -722,4 +722,7 @@ void nm_device_check_connectivity (NMDevice *self,

                                    gpointer user_data);

 NMConnectivityState nm_device_get_connectivity_state (NMDevice *self);

+

+const char *nm_device_state_to_str (NMDeviceState state);

+

 #endif /* __NETWORKMANAGER_DEVICE_H__ */

-- 

2.9.4

From c1fdd7063b9be81cbac1e256c0cca7ee8c6b4486 Mon Sep 17 00:00:00 2001

From: Thomas Haller <thaller@redhat.com>

Date: Wed, 7 Jun 2017 12:47:27 +0200

Subject: [PATCH 03/10] logging: add LOG3 macros

(cherry picked from commit 2ae891b5923afc2d4f2853f213d26538092b1c39)

(cherry picked from commit c5812a5fb9bee418e2d2c4f4ef4225d5cde86e87)

---

 src/nm-logging.h | 31 +++++++++++++++++++++++++++++++

 1 file changed, 31 insertions(+)

diff --git a/src/nm-logging.h b/src/nm-logging.h

index ff1fac7..91a4141 100644

--- a/src/nm-logging.h

+++ b/src/nm-logging.h

@@ -306,6 +306,37 @@ gboolean nm_logging_syslog_enabled (void);

 #define _LOG2t_err(errsv, ...) G_STMT_START { if (FALSE) { _NMLOG2_err (errsv, LOGL_TRACE, __VA_ARGS__); } } G_STMT_END

 #endif

+#define _NMLOG3_ENABLED(level) ( nm_logging_enabled ((level), (_NMLOG3_DOMAIN)) )

+

+#define _LOG3T(...)          _NMLOG3 (LOGL_TRACE, __VA_ARGS__)

+#define _LOG3D(...)          _NMLOG3 (LOGL_DEBUG, __VA_ARGS__)

+#define _LOG3I(...)          _NMLOG3 (LOGL_INFO , __VA_ARGS__)

+#define _LOG3W(...)          _NMLOG3 (LOGL_WARN , __VA_ARGS__)

+#define _LOG3E(...)          _NMLOG3 (LOGL_ERR  , __VA_ARGS__)

+

+#define _LOG3T_ENABLED(...)  _NMLOG3_ENABLED (LOGL_TRACE, ##__VA_ARGS__)

+#define _LOG3D_ENABLED(...)  _NMLOG3_ENABLED (LOGL_DEBUG, ##__VA_ARGS__)

+#define _LOG3I_ENABLED(...)  _NMLOG3_ENABLED (LOGL_INFO , ##__VA_ARGS__)

+#define _LOG3W_ENABLED(...)  _NMLOG3_ENABLED (LOGL_WARN , ##__VA_ARGS__)

+#define _LOG3E_ENABLED(...)  _NMLOG3_ENABLED (LOGL_ERR  , ##__VA_ARGS__)

+

+#define _LOG3T_err(errsv, ...) _NMLOG3_err (errsv, LOGL_TRACE, __VA_ARGS__)

+#define _LOG3D_err(errsv, ...) _NMLOG3_err (errsv, LOGL_DEBUG, __VA_ARGS__)

+#define _LOG3I_err(errsv, ...) _NMLOG3_err (errsv, LOGL_INFO , __VA_ARGS__)

+#define _LOG3W_err(errsv, ...) _NMLOG3_err (errsv, LOGL_WARN , __VA_ARGS__)

+#define _LOG3E_err(errsv, ...) _NMLOG3_err (errsv, LOGL_ERR  , __VA_ARGS__)

+

+#ifdef NM_MORE_LOGGING

+#define _LOG3t_ENABLED(...)    _NMLOG3_ENABLED (LOGL_TRACE, ##__VA_ARGS__)

+#define _LOG3t(...)            _NMLOG3 (LOGL_TRACE, __VA_ARGS__)

+#define _LOG3t_err(errsv, ...) _NMLOG3_err (errsv, LOGL_TRACE, __VA_ARGS__)

+#else

+/* still call the logging macros to get compile time checks, but they will be optimized out. */

+#define _LOG3t_ENABLED(...)    ( FALSE && (_NMLOG3_ENABLED (LOGL_TRACE, ##__VA_ARGS__)) )

+#define _LOG3t(...)            G_STMT_START { if (FALSE) { _NMLOG3 (LOGL_TRACE, __VA_ARGS__); } } G_STMT_END

+#define _LOG3t_err(errsv, ...) G_STMT_START { if (FALSE) { _NMLOG3_err (errsv, LOGL_TRACE, __VA_ARGS__); } } G_STMT_END

+#endif

+

 extern void (*_nm_logging_clear_platform_logging_cache) (void);

 /*****************************************************************************/

-- 

2.9.4

From 34397427cc2b8351f7068c911d085f946ed420bd Mon Sep 17 00:00:00 2001

From: Thomas Haller <thaller@redhat.com>

Date: Wed, 7 Jun 2017 12:46:10 +0200

Subject: [PATCH 04/10] manager: add logging macro _NMLOG2() for logging device

 messages

It unifies the way how we print the logging prefix, but also it

passes the ifname down for structured logging.

(cherry picked from commit 1f6078bcf5af88095d42ea2a2be002578cd3e76e)

(cherry picked from commit 22bf75162d96a2f6aa7084ba05d4eed21e9ca5e6)

---

 src/devices/nm-device-logging.h |  2 +-

 src/devices/nm-device.h         |  9 ++++

 src/nm-manager.c                | 97 ++++++++++++++++++++++-------------------

 3 files changed, 63 insertions(+), 45 deletions(-)

diff --git a/src/devices/nm-device-logging.h b/src/devices/nm-device-logging.h

index 5f95a91..f0c7e59 100644

--- a/src/devices/nm-device-logging.h

+++ b/src/devices/nm-device-logging.h

@@ -40,7 +40,7 @@ _nm_device_log_self_to_device (t *self) \

 		\

 		if (nm_logging_enabled (_level, _domain)) { \

 			typeof (*self) *const _self = (self); \

-			const char *const _ifname = _self ? nm_device_get_iface (_nm_device_log_self_to_device (_self)) : NULL; \

+			const char *const _ifname = _nm_device_get_iface (_nm_device_log_self_to_device (_self)); \

 			\

 			nm_log_obj (_level, _domain, \

 			            _ifname, NULL, \

diff --git a/src/devices/nm-device.h b/src/devices/nm-device.h

index edbb0aa..7229fb9 100644

--- a/src/devices/nm-device.h

+++ b/src/devices/nm-device.h

@@ -421,6 +421,15 @@ NMPlatform *nm_device_get_platform (NMDevice *self);

 const char *    nm_device_get_udi               (NMDevice *dev);

 const char *    nm_device_get_iface             (NMDevice *dev);

+

+static inline const char *

+_nm_device_get_iface (NMDevice *device)

+{

+	/* like nm_device_get_iface(), but gracefully accept NULL without

+	 * asserting. */

+	return device ? nm_device_get_iface (device) : NULL;

+}

+

 int             nm_device_get_ifindex           (NMDevice *dev);

 gboolean        nm_device_is_software           (NMDevice *dev);

 gboolean        nm_device_is_real               (NMDevice *dev);

diff --git a/src/nm-manager.c b/src/nm-manager.c

index 9a7b123..098d00d 100644

--- a/src/nm-manager.c

+++ b/src/nm-manager.c

@@ -222,19 +222,41 @@ NM_DEFINE_SINGLETON_INSTANCE (NMManager);

 #define _NMLOG_PREFIX_NAME      "manager"

 #define _NMLOG(level, domain, ...) \

     G_STMT_START { \

-        const NMLogLevel __level = (level); \

-        const NMLogDomain __domain = (domain); \

+        const NMLogLevel _level = (level); \

+        const NMLogDomain _domain = (domain); \

         \

-        if (nm_logging_enabled (__level, __domain)) { \

-            const NMManager *const __self = (self); \

-            char __sbuf[32]; \

+        if (nm_logging_enabled (_level, _domain)) { \

+            const NMManager *const _self = (self); \

+            char _sbuf[32]; \

             \

-            _nm_log (__level, __domain, 0, NULL, NULL, \

+            _nm_log (_level, _domain, 0, NULL, NULL, \

                      "%s%s: " _NM_UTILS_MACRO_FIRST (__VA_ARGS__), \

                      _NMLOG_PREFIX_NAME, \

-                     (__self && __self != singleton_instance) \

-                         ? nm_sprintf_buf (__sbuf, "[%p]", __self) \

-                         : "" \

+                     ((_self && _self != singleton_instance) \

+                         ? nm_sprintf_buf (_sbuf, "[%p]", _self) \

+                         : "") \

+                     _NM_UTILS_MACRO_REST (__VA_ARGS__)); \

+        } \

+    } G_STMT_END

+

+#define _NMLOG2(level, domain, device, ...) \

+    G_STMT_START { \

+        const NMLogLevel _level = (level); \

+        const NMLogDomain _domain = (domain); \

+        \

+        if (nm_logging_enabled (_level, _domain)) { \

+            const NMManager *const _self = (self); \

+            const char *const _ifname = _nm_device_get_iface (device); \

+            char _sbuf[32]; \

+            \

+            _nm_log (_level, _domain, 0, \

+                     _ifname, NULL, \

+                     "%s%s: %s%s%s" _NM_UTILS_MACRO_FIRST (__VA_ARGS__), \

+                     _NMLOG_PREFIX_NAME, \

+                     ((_self && _self != singleton_instance) \

+                         ? nm_sprintf_buf (_sbuf, "[%p]", _self) \

+                         : ""), \

+                     NM_PRINT_FMT_QUOTED (_ifname, "(", _ifname, "): ", "") \

                      _NM_UTILS_MACRO_REST (__VA_ARGS__)); \

         } \

     } G_STMT_END

@@ -983,8 +1005,8 @@ remove_device (NMManager *self,

 	NMManagerPrivate *priv = NM_MANAGER_GET_PRIVATE (self);

 	gboolean unmanage = FALSE;

-	_LOGD (LOGD_DEVICE, "(%s): removing device (allow_unmanage %d, managed %d)",

-	       nm_device_get_iface (device), allow_unmanage, nm_device_get_managed (device, FALSE));

+	_LOG2D (LOGD_DEVICE, device, "removing device (allow_unmanage %d, managed %d)",

+	        allow_unmanage, nm_device_get_managed (device, FALSE));

 	if (allow_unmanage && nm_device_get_managed (device, FALSE)) {

@@ -1481,9 +1503,7 @@ manager_update_radio_enabled (NMManager *self,

 		NMDevice *device = NM_DEVICE (iter->data);

 		if (nm_device_get_rfkill_type (device) == rstate->rtype) {

-			_LOGD (LOGD_RFKILL, "(%s): setting radio %s",

-			       nm_device_get_iface (device),

-			       enabled ? "enabled" : "disabled");

+			_LOG2D (LOGD_RFKILL, device, "setting radio %s", enabled ? "enabled" : "disabled");

 			nm_device_set_enabled (device, enabled);

 		}

 	}

@@ -1724,13 +1744,13 @@ get_existing_connection (NMManager *self,

 		if (master_ifindex) {

 			master = nm_manager_get_device_by_ifindex (self, master_ifindex);

 			if (!master) {

-				_LOGD (LOGD_DEVICE, "(%s): cannot generate connection for slave before its master (%s/%d)",

-				       nm_device_get_iface (device), nm_platform_link_get_name (NM_PLATFORM_GET, master_ifindex), master_ifindex);

+				_LOG2D (LOGD_DEVICE, device, "cannot generate connection for slave before its master (%s/%d)",

+				       nm_platform_link_get_name (NM_PLATFORM_GET, master_ifindex), master_ifindex);

 				return NULL;

 			}

 			if (!nm_device_get_act_request (master)) {

-				_LOGD (LOGD_DEVICE, "(%s): cannot generate connection for slave before master %s activates",

-				       nm_device_get_iface (device), nm_device_get_iface (master));

+				_LOG2D (LOGD_DEVICE, device, "cannot generate connection for slave before master %s activates",

+				       nm_device_get_iface (master));

 				return NULL;

 			}

 		}

@@ -1811,20 +1831,18 @@ get_existing_connection (NMManager *self,

 	}

 	if (matched) {

-		_LOGI (LOGD_DEVICE, "(%s): found matching connection '%s' (%s)%s",

-		       nm_device_get_iface (device),

-		       nm_settings_connection_get_id (matched),

-		       nm_settings_connection_get_uuid (matched),

-		       assume_state_connection_uuid && nm_streq (assume_state_connection_uuid, nm_settings_connection_get_uuid (matched))

-		           ? " (indicated)" : " (guessed)");

+		_LOG2I (LOGD_DEVICE, device, "found matching connection '%s' (%s)%s",

+		        nm_settings_connection_get_id (matched),

+		        nm_settings_connection_get_uuid (matched),

+		        assume_state_connection_uuid && nm_streq (assume_state_connection_uuid, nm_settings_connection_get_uuid (matched))

+		            ? " (indicated)" : " (guessed)");

 		g_object_unref (connection);

 		nm_device_assume_state_reset (device);

 		return matched;

 	}

-	_LOGD (LOGD_DEVICE, "(%s): generated connection '%s'",

-	       nm_device_get_iface (device),

-	       nm_connection_get_id (connection));

+	_LOG2D (LOGD_DEVICE, device, "generated connection '%s'",

+	        nm_connection_get_id (connection));

 	nm_device_assume_state_reset (device);

@@ -1837,8 +1855,7 @@ get_existing_connection (NMManager *self,

 		if (out_generated)

 			*out_generated = TRUE;

 	} else {

-		_LOGW (LOGD_SETTINGS, "(%s) Couldn't save generated connection '%s': %s",

-		       nm_device_get_iface (device),

+		_LOG2W (LOGD_SETTINGS, device, "Couldn't save generated connection '%s': %s",

 		       nm_connection_get_id (connection),

 		       error->message);

 		g_clear_error (&error);

@@ -1873,13 +1890,11 @@ recheck_assume_connection (NMManager *self,

 	connection = get_existing_connection (self, device, &generated);

 	if (!connection) {

-		_LOGD (LOGD_DEVICE, "(%s): can't assume; no connection",

-		       nm_device_get_iface (device));

+		_LOG2D (LOGD_DEVICE, device, "can't assume; no connection");

 		return FALSE;

 	}

-	_LOGD (LOGD_DEVICE, "(%s): will attempt to assume connection",

-	       nm_device_get_iface (device));

+	_LOG2D (LOGD_DEVICE, device, "will attempt to assume connection");

 	nm_device_sys_iface_state_set (device,

 	                               generated

@@ -1926,9 +1941,7 @@ recheck_assume_connection (NMManager *self,

 			}

 			if (generated) {

-				_LOGD (LOGD_DEVICE, "(%s): connection assumption failed. Deleting generated connection",

-				       nm_device_get_iface (device));

-

+				_LOG2D (LOGD_DEVICE, device, "connection assumption failed. Deleting generated connection");

 				nm_settings_connection_delete (connection, NULL, NULL);

 			} else {

 				if (nm_device_sys_iface_state_get (device) == NM_DEVICE_SYS_IFACE_STATE_ASSUME)

@@ -2182,7 +2195,7 @@ add_device (NMManager *self, NMDevice *device, GError **error)

 	                               manager_sleeping (self));

 	dbus_path = nm_exported_object_export (NM_EXPORTED_OBJECT (device));

-	_LOGI (LOGD_DEVICE, "(%s): new %s device (%s)", iface, type_desc, dbus_path);

+	_LOG2I (LOGD_DEVICE, device, "new %s device (%s)", type_desc, dbus_path);

 	nm_settings_device_added (priv->settings, device);

 	g_signal_emit (self, signals[INTERNAL_DEVICE_ADDED], 0, device);

@@ -2221,8 +2234,7 @@ factory_device_added_cb (NMDeviceFactory *factory,

 		add_device (self, device, NULL);

 		_device_realize_finish (self, device, NULL);

 	} else {

-		_LOGW (LOGD_DEVICE, "(%s): failed to realize device: %s",

-		       nm_device_get_iface (device), error->message);

+		_LOG2W (LOGD_DEVICE, device, "failed to realize device: %s", error->message);

 		g_error_free (error);

 	}

 }

@@ -2414,9 +2426,7 @@ _platform_link_cb_idle (PlatformLinkCbData *data)

 				nm_device_sys_iface_state_set (device, NM_DEVICE_SYS_IFACE_STATE_REMOVED);

 				/* Our software devices stick around until their connection is removed */

 				if (!nm_device_unrealize (device, FALSE, &error)) {

-					_LOGW (LOGD_DEVICE, "(%s): failed to unrealize: %s",

-					       nm_device_get_iface (device),

-					       error->message);

+					_LOG2W (LOGD_DEVICE, device, "failed to unrealize: %s", error->message);

 					g_clear_error (&error);

 					remove_device (self, device, FALSE, TRUE);

 				}

@@ -5172,8 +5182,7 @@ handle_firmware_changed (gpointer user_data)

 		if (   nm_device_get_firmware_missing (candidate)

 		    && (state == NM_DEVICE_STATE_UNAVAILABLE)) {

-			_LOGI (LOGD_CORE, "(%s): firmware may now be available",

-			       nm_device_get_iface (candidate));

+			_LOG2I (LOGD_CORE, candidate, "firmware may now be available");

 			/* Re-set unavailable state to try bringing the device up again */

 			nm_device_state_changed (candidate,

-- 

2.9.4

From da914ee814f86d87eda5676fa7a1cbf5bcbf264e Mon Sep 17 00:00:00 2001

From: Thomas Haller <thaller@redhat.com>

Date: Wed, 7 Jun 2017 12:46:10 +0200

Subject: [PATCH 05/10] manager: add logging macro _NMLOG3() for logging

 connection messages

It unifies the way how we print the logging prefix, but also it

passes the con_uuid down for structured logging.

(cherry picked from commit 6962f14d4a74c192a81604b7de40a94d13530dc6)

(cherry picked from commit 36b99ccf5f430f0e70478e5bae314e7893850cde)

---

 libnm-core/nm-core-internal.h | 18 ++++++++++++++++

 src/nm-manager.c              | 50 +++++++++++++++++++++++++++++++------------

 2 files changed, 54 insertions(+), 14 deletions(-)

diff --git a/libnm-core/nm-core-internal.h b/libnm-core/nm-core-internal.h

index ac292bf..91967ce 100644

--- a/libnm-core/nm-core-internal.h

+++ b/libnm-core/nm-core-internal.h

@@ -343,6 +343,24 @@ _nm_setting_bond_get_option_type (NMSettingBond *setting, const char *name);

 /*****************************************************************************/

+/* nm_connection_get_uuid() asserts against NULL, which is the right thing to

+ * do in order to catch bugs. However, sometimes that behavior is inconvenient.

+ * Just try or return NULL. */

+

+static inline const char *

+_nm_connection_get_id (NMConnection *connection)

+{

+	return connection ? nm_connection_get_id (connection) : NULL;

+}

+

+static inline const char *

+_nm_connection_get_uuid (NMConnection *connection)

+{

+	return connection ? nm_connection_get_uuid (connection) : NULL;

+}

+

+/*****************************************************************************/

+

 typedef enum {

 	NM_BOND_MODE_UNKNOWN = 0,

 	NM_BOND_MODE_ROUNDROBIN,

diff --git a/src/nm-manager.c b/src/nm-manager.c

index 098d00d..da94aac 100644

--- a/src/nm-manager.c

+++ b/src/nm-manager.c

@@ -261,6 +261,29 @@ NM_DEFINE_SINGLETON_INSTANCE (NMManager);

         } \

     } G_STMT_END

+#define _NMLOG3(level, domain, connection, ...) \

+    G_STMT_START { \

+        const NMLogLevel _level = (level); \

+        const NMLogDomain _domain = (domain); \

+        \

+        if (nm_logging_enabled (_level, _domain)) { \

+            const NMManager *const _self = (self); \

+            NMConnection *const _connection = (connection); \

+            const char *const _con_id = _nm_connection_get_id (_connection); \

+            char _sbuf[32]; \

+            \

+            _nm_log (_level, _domain, 0, \

+                     NULL, _nm_connection_get_uuid (_connection), \

+                     "%s%s: %s%s%s" _NM_UTILS_MACRO_FIRST (__VA_ARGS__), \

+                     _NMLOG_PREFIX_NAME, \

+                     ((_self && _self != singleton_instance) \

+                         ? nm_sprintf_buf (_sbuf, "[%p]", _self) \

+                         : ""), \

+                     NM_PRINT_FMT_QUOTED (_con_id, "(", _con_id, ") ", "") \

+                     _NM_UTILS_MACRO_REST (__VA_ARGS__)); \

+        } \

+    } G_STMT_END

+

 /*****************************************************************************/

 static NM_CACHED_QUARK_FCN ("autoconnect-root", autoconnect_root_quark)

@@ -1260,8 +1283,8 @@ system_create_virtual_device (NMManager *self, NMConnection *connection)

 	iface = nm_manager_get_connection_iface (self, connection, &parent, &error);

 	if (!iface) {

-		_LOGD (LOGD_DEVICE, "(%s) can't get a name of a virtual device: %s",

-		       nm_connection_get_id (connection), error->message);

+		_LOG3D (LOGD_DEVICE, connection, "can't get a name of a virtual device: %s",

+		        error->message);

 		g_error_free (error);

 		return NULL;

 	}

@@ -1272,8 +1295,8 @@ system_create_virtual_device (NMManager *self, NMConnection *connection)

 		if (nm_device_check_connection_compatible (candidate, connection)) {

 			if (nm_device_is_real (candidate)) {

-				_LOGD (LOGD_DEVICE, "(%s) already created virtual interface name %s",

-				       nm_connection_get_id (connection), iface);

+				_LOG3D (LOGD_DEVICE, connection, "already created virtual interface name %s",

+				       iface);

 				return NULL;

 			}

@@ -1287,27 +1310,26 @@ system_create_virtual_device (NMManager *self, NMConnection *connection)

 		factory = nm_device_factory_manager_find_factory_for_connection (connection);

 		if (!factory) {

-			_LOGE (LOGD_DEVICE, "(%s:%s) NetworkManager plugin for '%s' unavailable",

-			       nm_connection_get_id (connection), iface,

+			_LOG3E (LOGD_DEVICE, connection, "(%s) NetworkManager plugin for '%s' unavailable",

+			       iface,

 			       nm_connection_get_connection_type (connection));

 			return NULL;

 		}

 		device = nm_device_factory_create_device (factory, iface, NULL, connection, NULL, &error);

 		if (!device) {

-			_LOGW (LOGD_DEVICE, "(%s) factory can't create the device: %s",

-			       nm_connection_get_id (connection), error->message);

+			_LOG3W (LOGD_DEVICE, connection, "factory can't create the device: %s",

+			        error->message);

 			g_error_free (error);

 			return NULL;

 		}

-		_LOGD (LOGD_DEVICE, "(%s) create virtual device %s",

-		       nm_connection_get_id (connection),

+		_LOG3D (LOGD_DEVICE, connection, "create virtual device %s",

 		       nm_device_get_iface (device));

 		if (!add_device (self, device, &error)) {

-			_LOGW (LOGD_DEVICE, "(%s) can't register the device with manager: %s",

-			       nm_connection_get_id (connection), error->message);

+			_LOG3W (LOGD_DEVICE, connection, "can't register the device with manager: %s",

+			        error->message);

 			g_error_free (error);

 			g_object_unref (device);

 			return NULL;

@@ -1335,8 +1357,8 @@ system_create_virtual_device (NMManager *self, NMConnection *connection)

 		/* Create any backing resources the device needs */

 		if (!nm_device_create_and_realize (device, connection, parent, &error)) {

-			_LOGW (LOGD_DEVICE, "(%s) couldn't create the device: %s",

-			       nm_connection_get_id (connection), error->message);

+			_LOG3W (LOGD_DEVICE, connection, "couldn't create the device: %s",

+			        error->message);

 			g_error_free (error);

 			remove_device (self, device, FALSE, TRUE);

 			return NULL;

-- 

2.9.4

From b4dc736b2b6c60324461e128b9f57364d127cc6a Mon Sep 17 00:00:00 2001

From: Thomas Haller <thaller@redhat.com>

Date: Wed, 7 Jun 2017 13:13:55 +0200

Subject: [PATCH 06/10] manager: add "rfkill" prefix to related logging

 messages

(cherry picked from commit dd53c879d2395de667fefb9bd8fc1125b85a7977)

(cherry picked from commit 01fd9df6e589ef623a069cb6c46230ba77ad6b0a)

---

 src/nm-manager.c | 22 +++++++++++-----------

 1 file changed, 11 insertions(+), 11 deletions(-)

diff --git a/src/nm-manager.c b/src/nm-manager.c

index da94aac..d7437e6 100644

--- a/src/nm-manager.c

+++ b/src/nm-manager.c

@@ -1525,7 +1525,7 @@ manager_update_radio_enabled (NMManager *self,

 		NMDevice *device = NM_DEVICE (iter->data);

 		if (nm_device_get_rfkill_type (device) == rstate->rtype) {

-			_LOG2D (LOGD_RFKILL, device, "setting radio %s", enabled ? "enabled" : "disabled");

+			_LOG2D (LOGD_RFKILL, device, "rfkill: setting radio %s", enabled ? "enabled" : "disabled");

 			nm_device_set_enabled (device, enabled);

 		}

 	}

@@ -1570,14 +1570,14 @@ manager_rfkill_update_one_type (NMManager *self,

 	/* Print out all states affecting device enablement */

 	if (rstate->desc) {

-		_LOGD (LOGD_RFKILL, "%s hw-enabled %d sw-enabled %d",

+		_LOGD (LOGD_RFKILL, "rfkill: %s hw-enabled %d sw-enabled %d",

 		       rstate->desc, rstate->hw_enabled, rstate->sw_enabled);

 	}

 	/* Log new killswitch state */

 	new_rfkilled = rstate->hw_enabled && rstate->sw_enabled;

 	if (old_rfkilled != new_rfkilled) {

-		_LOGI (LOGD_RFKILL, "%s now %s by radio killswitch",

+		_LOGI (LOGD_RFKILL, "rfkill: %s now %s by radio killswitch",

 		       rstate->desc,

 		       new_rfkilled ? "enabled" : "disabled");

 	}

@@ -4531,7 +4531,7 @@ do_sleep_wake (NMManager *self, gboolean sleeping_changed)

 				gboolean enabled = radio_enabled_for_rstate (rstate, TRUE);

 				if (rstate->desc) {

-					_LOGD (LOGD_RFKILL, "%s %s devices (hw_enabled %d, sw_enabled %d, user_enabled %d)",

+					_LOGD (LOGD_RFKILL, "rfkill: %s %s devices (hw_enabled %d, sw_enabled %d, user_enabled %d)",

 					       enabled ? "enabling" : "disabling",

 					       rstate->desc, rstate->hw_enabled, rstate->sw_enabled, rstate->user_enabled);

 				}

@@ -5128,7 +5128,7 @@ nm_manager_start (NMManager *self, GError **error)

 		update_rstate_from_rfkill (priv->rfkill_mgr, rstate);

 		if (rstate->desc) {

-			_LOGI (LOGD_RFKILL, "%s %s by radio killswitch; %s by state file",

+			_LOGI (LOGD_RFKILL, "rfkill: %s %s by radio killswitch; %s by state file",

 			       rstate->desc,

 			       (rstate->hw_enabled && rstate->sw_enabled) ? "enabled" : "disabled",

 			       rstate->user_enabled ? "enabled" : "disabled");

@@ -5836,12 +5836,12 @@ rfkill_change (NMManager *self, const char *desc, RfKillType rtype, gboolean ena

 	fd = open ("/dev/rfkill", O_RDWR | O_CLOEXEC);

 	if (fd < 0) {

 		if (errno == EACCES)

-			_LOGW (LOGD_RFKILL, "(%s): failed to open killswitch device", desc);

+			_LOGW (LOGD_RFKILL, "rfkill: (%s): failed to open killswitch device", desc);

 		return;

 	}

 	if (fcntl (fd, F_SETFL, O_NONBLOCK) < 0) {

-		_LOGW (LOGD_RFKILL, "(%s): failed to set killswitch device for "

+		_LOGW (LOGD_RFKILL, "rfkill: (%s): failed to set killswitch device for "

 		       "non-blocking operation", desc);

 		close (fd);