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);
 		return;
@@ -5863,14 +5863,14 @@ rfkill_change (NMManager *self, const char *desc, RfKillType rtype, gboolean ena
 
 	len = write (fd, &event, sizeof (event));
 	if (len < 0) {
-		_LOGW (LOGD_RFKILL, "(%s): failed to change WiFi killswitch state: (%d) %s",
+		_LOGW (LOGD_RFKILL, "rfkill: (%s): failed to change WiFi killswitch state: (%d) %s",
 		       desc, errno, g_strerror (errno));
 	} else if (len == sizeof (event)) {
-		_LOGI (LOGD_RFKILL, "%s hardware radio set %s",
+		_LOGI (LOGD_RFKILL, "rfkill: %s hardware radio set %s",
 		       desc, enabled ? "enabled" : "disabled");
 	} else {
 		/* Failed to write full structure */
-		_LOGW (LOGD_RFKILL, "(%s): failed to change WiFi killswitch state", desc);
+		_LOGW (LOGD_RFKILL, "rfkill: (%s): failed to change WiFi killswitch state", desc);
 	}
 
 	close (fd);
@@ -5889,7 +5889,7 @@ manager_radio_user_toggled (NMManager *self,
 		return;
 
 	if (rstate->desc) {
-		_LOGD (LOGD_RFKILL, "(%s): setting radio %s by user",
+		_LOGD (LOGD_RFKILL, "rfkill: (%s): setting radio %s by user",
 		       rstate->desc,
 		       enabled ? "enabled" : "disabled");
 	}
-- 
2.9.4


From cf805b925c93cae145e354afd0cc05844ec3cd62 Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Wed, 7 Jun 2017 13:30:08 +0200
Subject: [PATCH 07/10] manager: add more logging to
 recheck_assume_connection()

and give all lines a logging prefix.

(cherry picked from commit 94534e032788e69690c2affcd09d1f306ffa3840)
(cherry picked from commit 7e2d64a8b23e4606f15fc66ebf953d5effb16ac3)
---
 src/nm-manager.c | 13 +++++++++----
 1 file changed, 9 insertions(+), 4 deletions(-)

diff --git a/src/nm-manager.c b/src/nm-manager.c
index d7437e6..3c190eb 100644
--- a/src/nm-manager.c
+++ b/src/nm-manager.c
@@ -1901,22 +1901,27 @@ recheck_assume_connection (NMManager *self,
 
 	if (!nm_device_get_managed (device, FALSE)) {
 		nm_device_assume_state_reset (device);
+		_LOG2D (LOGD_DEVICE, device, "assume: don't assume because %s", "not managed");
 		return FALSE;
 	}
 
 	state = nm_device_get_state (device);
 	if (state > NM_DEVICE_STATE_DISCONNECTED) {
 		nm_device_assume_state_reset (device);
+		_LOG2D (LOGD_DEVICE, device, "assume: don't assume due to device state %s",
+		        nm_device_state_to_str (state));
 		return FALSE;
 	}
 
 	connection = get_existing_connection (self, device, &generated);
 	if (!connection) {
-		_LOG2D (LOGD_DEVICE, device, "can't assume; no connection");
+		_LOG2D (LOGD_DEVICE, device, "assume: don't assume because %s", "no connection was generated");
 		return FALSE;
 	}
 
-	_LOG2D (LOGD_DEVICE, device, "will attempt to assume connection");
+	_LOG2D (LOGD_DEVICE, device, "assume: will attempt to assume %sconnection %s",
+	        generated ? "generated " : "",
+	        nm_connection_get_uuid (NM_CONNECTION (connection)));
 
 	nm_device_sys_iface_state_set (device,
 	                               generated
@@ -1951,7 +1956,7 @@ recheck_assume_connection (NMManager *self,
 		                                 &error);
 
 		if (!active) {
-			_LOGW (LOGD_DEVICE, "assumed connection %s failed to activate: %s",
+			_LOGW (LOGD_DEVICE, "assume: assumed connection %s failed to activate: %s",
 			       nm_connection_get_path (NM_CONNECTION (connection)),
 			       error->message);
 			g_error_free (error);
@@ -1963,7 +1968,7 @@ recheck_assume_connection (NMManager *self,
 			}
 
 			if (generated) {
-				_LOG2D (LOGD_DEVICE, device, "connection assumption failed. Deleting generated connection");
+				_LOG2D (LOGD_DEVICE, device, "assume: deleting generated connection after assuming failed");
 				nm_settings_connection_delete (connection, NULL, NULL);
 			} else {
 				if (nm_device_sys_iface_state_get (device) == NM_DEVICE_SYS_IFACE_STATE_ASSUME)
-- 
2.9.4


From 7efa2f15760e2ae7e550ad11f0bb49e66748334b Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Wed, 7 Jun 2017 13:44:07 +0200
Subject: [PATCH 08/10] device: remove logging for emitting RECHECK_ASSUME
 signal

The device's RECHECK_ASSUME signal has only NMManager as subscriber
and it immediately calls recheck_assume_connection().

With the previous commit, recheck_assume_connection() always logs
a debug message, so we don't need this duplicate message anymore.

(cherry picked from commit cc47a6a8b2c16b0ea1df95384b794a2e8d47cfeb)
(cherry picked from commit c254277f409f629fe0b728e9a2f87c418181762d)
---
 src/devices/nm-device.c | 5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c
index fdf88c9..36ba9f9 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -4392,10 +4392,9 @@ nm_device_emit_recheck_assume (gpointer user_data)
 	priv = NM_DEVICE_GET_PRIVATE (self);
 
 	priv->recheck_assume_id = 0;
-	if (!nm_device_get_act_request (self)) {
-		_LOGD (LOGD_DEVICE, "emit RECHECK_ASSUME signal");
+	if (!nm_device_get_act_request (self))
 		g_signal_emit (self, signals[RECHECK_ASSUME], 0);
-	}
+
 	return G_SOURCE_REMOVE;
 }
 
-- 
2.9.4


From cb7d9f5ed5ccae171712d3cdc109978bb34f5607 Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Wed, 7 Jun 2017 16:41:06 +0200
Subject: [PATCH 09/10] manager: cleanup logging message during
 recheck_assume_connection()/get_existing_connection()

recheck_assume_connection() calls get_existing_connection(). We want *one* logging
message telling what's happening. Let get_existing_connection() log "assume:"
messages and remove duplicate messages from recheck_assume_connection().

(cherry picked from commit 962f8f42d9d04eeb794d931ccaad775ca05233e2)
(cherry picked from commit 70b4684d7e975e2ce120e11c27b8d3f7ac2e0cc2)
---
 src/nm-manager.c | 52 ++++++++++++++++++++++++----------------------------
 1 file changed, 24 insertions(+), 28 deletions(-)

diff --git a/src/nm-manager.c b/src/nm-manager.c
index 3c190eb..fa220f1 100644
--- a/src/nm-manager.c
+++ b/src/nm-manager.c
@@ -1744,7 +1744,7 @@ get_existing_connection (NMManager *self,
                          gboolean *out_generated)
 {
 	NMManagerPrivate *priv = NM_MANAGER_GET_PRIVATE (self);
-	NMConnection *connection = NULL;
+	gs_unref_object NMConnection *connection = NULL;
 	NMSettingsConnection *added = NULL;
 	GError *error = NULL;
 	NMDevice *master = NULL;
@@ -1766,13 +1766,15 @@ get_existing_connection (NMManager *self,
 		if (master_ifindex) {
 			master = nm_manager_get_device_by_ifindex (self, master_ifindex);
 			if (!master) {
-				_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);
+				_LOG2D (LOGD_DEVICE, device, "assume: don't assume because "
+				        "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)) {
-				_LOG2D (LOGD_DEVICE, device, "cannot generate connection for slave before master %s activates",
-				       nm_device_get_iface (master));
+				_LOG2D (LOGD_DEVICE, device, "assume: don't assume because "
+				        "cannot generate connection for slave before master %s activates",
+				        nm_device_get_iface (master));
 				return NULL;
 			}
 		}
@@ -1788,6 +1790,7 @@ get_existing_connection (NMManager *self,
 	if (!connection) {
 		if (!maybe_later)
 			nm_device_assume_state_reset (device);
+		_LOG2D (LOGD_DEVICE, device, "assume: don't assume due to failure to generate connection");
 		return NULL;
 	}
 
@@ -1853,38 +1856,36 @@ get_existing_connection (NMManager *self,
 	}
 
 	if (matched) {
-		_LOG2I (LOGD_DEVICE, device, "found matching connection '%s' (%s)%s",
+		_LOG2I (LOGD_DEVICE, device, "assume: will attempt to assume 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;
 	}
 
-	_LOG2D (LOGD_DEVICE, device, "generated connection '%s'",
-	        nm_connection_get_id (connection));
+	_LOG2D (LOGD_DEVICE, device, "assume: generated connection '%s' (%s)",
+	        nm_connection_get_id (connection),
+	        nm_connection_get_uuid (connection));
 
 	nm_device_assume_state_reset (device);
 
 	added = nm_settings_add_connection (priv->settings, connection, FALSE, &error);
-	if (added) {
-		nm_settings_connection_set_flags (NM_SETTINGS_CONNECTION (added),
-		                                  NM_SETTINGS_CONNECTION_FLAGS_NM_GENERATED |
-		                                  NM_SETTINGS_CONNECTION_FLAGS_VOLATILE,
-		                                  TRUE);
-		if (out_generated)
-			*out_generated = TRUE;
-	} else {
-		_LOG2W (LOGD_SETTINGS, device, "Couldn't save generated connection '%s': %s",
+	if (!added) {
+		_LOG2W (LOGD_SETTINGS, device, "assume: failure to save generated connection '%s': %s",
 		       nm_connection_get_id (connection),
 		       error->message);
-		g_clear_error (&error);
+		g_error_free (error);
+		return NULL;
 	}
-	g_object_unref (connection);
 
-	return added ? added : NULL;
+	nm_settings_connection_set_flags (NM_SETTINGS_CONNECTION (added),
+	                                  NM_SETTINGS_CONNECTION_FLAGS_NM_GENERATED |
+	                                  NM_SETTINGS_CONNECTION_FLAGS_VOLATILE,
+	                                  TRUE);
+	NM_SET_OUT (out_generated, TRUE);
+	return added;
 }
 
 static gboolean
@@ -1914,14 +1915,9 @@ recheck_assume_connection (NMManager *self,
 	}
 
 	connection = get_existing_connection (self, device, &generated);
-	if (!connection) {
-		_LOG2D (LOGD_DEVICE, device, "assume: don't assume because %s", "no connection was generated");
+	/* log  no reason. get_existing_connection() already does it. */
+	if (!connection)
 		return FALSE;
-	}
-
-	_LOG2D (LOGD_DEVICE, device, "assume: will attempt to assume %sconnection %s",
-	        generated ? "generated " : "",
-	        nm_connection_get_uuid (NM_CONNECTION (connection)));
 
 	nm_device_sys_iface_state_set (device,
 	                               generated
-- 
2.9.4


From a0ded04b454b32dfa6a0d3bb357e950941a65684 Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Wed, 7 Jun 2017 17:04:33 +0200
Subject: [PATCH 10/10] device: suppress logging and return error reason from
 nm_device_generate_connection()

Don't log in a function that basically just inspects state, without
mutating it. Instead, pass the reason why a connection could not be
generated to the caller so that we have one sensible log message.

(cherry picked from commit 0c26ffd638b1db490ae72b105feb697b61fc43cb)
(cherry picked from commit 78ff06c539b36521a82d4d65b573678a1f91b531)
---
 src/devices/nm-device.c | 56 +++++++++++++++++++++++++++----------------------
 src/devices/nm-device.h |  3 ++-
 src/nm-manager.c        |  6 ++++--
 3 files changed, 37 insertions(+), 28 deletions(-)

diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c
index 36ba9f9..246a18f 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -4111,29 +4111,37 @@ nm_device_master_update_slave_connection (NMDevice *self,
 }
 
 NMConnection *
-nm_device_generate_connection (NMDevice *self, NMDevice *master, gboolean *out_maybe_later)
+nm_device_generate_connection (NMDevice *self,
+                               NMDevice *master,
+                               gboolean *out_maybe_later,
+                               GError **error)
 {
 	NMDeviceClass *klass = NM_DEVICE_GET_CLASS (self);
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
 	const char *ifname = nm_device_get_iface (self);
-	NMConnection *connection;
+	gs_unref_object NMConnection *connection = NULL;
 	NMSetting *s_con;
 	NMSetting *s_ip4;
 	NMSetting *s_ip6;
 	char uuid[37];
 	const char *ip4_method, *ip6_method;
-	GError *error = NULL;
+	GError *local = NULL;
 	const NMPlatformLink *pllink;
 
 	NM_SET_OUT (out_maybe_later, FALSE);
 
 	/* If update_connection() is not implemented, just fail. */
-	if (!klass->update_connection)
+	if (!klass->update_connection) {
+		g_set_error (error, NM_DEVICE_ERROR, NM_DEVICE_ERROR_FAILED,
+		             "device class %s does not support generating a connection",
+		             G_OBJECT_TYPE_NAME (self));
 		return NULL;
+	}
 
 	/* Return NULL if device is unconfigured. */
 	if (!device_has_config (self)) {
-		_LOGD (LOGD_DEVICE, "device has no existing configuration");
+		g_set_error (error, NM_DEVICE_ERROR, NM_DEVICE_ERROR_FAILED,
+		             "device has no existing configuration");
 		return NULL;
 	}
 
@@ -4156,12 +4164,11 @@ nm_device_generate_connection (NMDevice *self, NMDevice *master, gboolean *out_m
 		if (!nm_device_master_update_slave_connection (master,
 		                                               self,
 		                                               connection,
-		                                               &error))
-		{
-			_LOGE (LOGD_DEVICE, "master device '%s' failed to update slave connection: %s",
-			       nm_device_get_iface (master), error->message);
-			g_error_free (error);
-			g_object_unref (connection);
+		                                               &local)) {
+			g_set_error (error, NM_DEVICE_ERROR, NM_DEVICE_ERROR_FAILED,
+			             "master device '%s' failed to update slave connection: %s",
+			             nm_device_get_iface (master), local->message);
+			g_error_free (local);
 			return NULL;
 		}
 	} else {
@@ -4174,7 +4181,6 @@ nm_device_generate_connection (NMDevice *self, NMDevice *master, gboolean *out_m
 
 		pllink = nm_platform_link_get (nm_device_get_platform (self), priv->ifindex);
 		if (pllink && pllink->inet6_token.id) {
-			_LOGD (LOGD_IP6, "IPv6 tokenized identifier present");
 			g_object_set (s_ip6,
 			              NM_SETTING_IP6_CONFIG_ADDR_GEN_MODE, NM_IN6_ADDR_GEN_MODE_EUI64,
 			              NM_SETTING_IP6_CONFIG_TOKEN, nm_utils_inet6_interface_identifier_to_token (pllink->inet6_token, NULL),
@@ -4184,11 +4190,11 @@ nm_device_generate_connection (NMDevice *self, NMDevice *master, gboolean *out_m
 
 	klass->update_connection (self, connection);
 
-	/* Check the connection in case of update_connection() bug. */
-	if (!nm_connection_verify (connection, &error)) {
-		_LOGE (LOGD_DEVICE, "Generated connection does not verify: %s", error->message);
-		g_clear_error (&error);
-		g_object_unref (connection);
+	if (!nm_connection_verify (connection, &local)) {
+		g_set_error (error, NM_DEVICE_ERROR, NM_DEVICE_ERROR_FAILED,
+		             "generated connection does not verify: %s",
+		             local->message);
+		g_error_free (local);
 		return NULL;
 	}
 
@@ -4201,28 +4207,28 @@ nm_device_generate_connection (NMDevice *self, NMDevice *master, gboolean *out_m
 	    && g_strcmp0 (ip6_method, NM_SETTING_IP6_CONFIG_METHOD_IGNORE) == 0
 	    && !nm_setting_connection_get_master (NM_SETTING_CONNECTION (s_con))
 	    && !priv->slaves) {
-		_LOGD (LOGD_DEVICE, "ignoring generated connection (no IP and not in master-slave relationship)");
 		NM_SET_OUT (out_maybe_later, TRUE);
-		g_object_unref (connection);
-		connection = NULL;
+		g_set_error_literal (error, NM_DEVICE_ERROR, NM_DEVICE_ERROR_FAILED,
+		                     "ignoring generated connection (no IP and not in master-slave relationship)");
+		return NULL;
 	}
 
 	/* Ignore any IPv6LL-only, not master connections without slaves,
 	 * unless they are in the assume-ipv6ll-only list.
 	 */
-	if (   connection
-	    && g_strcmp0 (ip4_method, NM_SETTING_IP4_CONFIG_METHOD_DISABLED) == 0
+	if (   g_strcmp0 (ip4_method, NM_SETTING_IP4_CONFIG_METHOD_DISABLED) == 0
 	    && g_strcmp0 (ip6_method, NM_SETTING_IP6_CONFIG_METHOD_LINK_LOCAL) == 0
 	    && !nm_setting_connection_get_master (NM_SETTING_CONNECTION (s_con))
 	    && !priv->slaves
 	    && !nm_config_data_get_assume_ipv6ll_only (NM_CONFIG_GET_DATA, self)) {
 		_LOGD (LOGD_DEVICE, "ignoring generated connection (IPv6LL-only and not in master-slave relationship)");
 		NM_SET_OUT (out_maybe_later, TRUE);
-		g_object_unref (connection);
-		connection = NULL;
+		g_set_error_literal (error, NM_DEVICE_ERROR, NM_DEVICE_ERROR_FAILED,
+		                    "ignoring generated connection (IPv6LL-only and not in master-slave relationship)");
+		return NULL;
 	}
 
-	return connection;
+	return g_steal_pointer (&connection);
 }
 
 gboolean
diff --git a/src/devices/nm-device.h b/src/devices/nm-device.h
index 7229fb9..50d9b97 100644
--- a/src/devices/nm-device.h
+++ b/src/devices/nm-device.h
@@ -498,7 +498,8 @@ gboolean        nm_device_has_carrier           (NMDevice *dev);
 
 NMConnection * nm_device_generate_connection (NMDevice *self,
                                               NMDevice *master,
-                                              gboolean *out_maybe_later);
+                                              gboolean *out_maybe_later,
+                                              GError **error);
 
 gboolean nm_device_master_update_slave_connection (NMDevice *master,
                                                    NMDevice *slave,
diff --git a/src/nm-manager.c b/src/nm-manager.c
index fa220f1..abcd0ee 100644
--- a/src/nm-manager.c
+++ b/src/nm-manager.c
@@ -1786,11 +1786,13 @@ get_existing_connection (NMManager *self,
 	 * update_connection() implemented, otherwise nm_device_generate_connection()
 	 * returns NULL.
 	 */
-	connection = nm_device_generate_connection (device, master, &maybe_later);
+	connection = nm_device_generate_connection (device, master, &maybe_later, &error);
 	if (!connection) {
 		if (!maybe_later)
 			nm_device_assume_state_reset (device);
-		_LOG2D (LOGD_DEVICE, device, "assume: don't assume due to failure to generate connection");
+		_LOG2D (LOGD_DEVICE, device, "assume: cannot generate connection: %s",
+		        error->message);
+		g_error_free (error);
 		return NULL;
 	}
 
-- 
2.9.4