dhcp: call synchronous Notify D-Bus method from nm-dhcp-helperbg/th/dhcp-helper-sync-notify-rh1372854-nm-1-2

A D-Bus signal is asynchronous and it can happen that nm-dhcp-helper
emits the "Event" signal before the server is able to register a handler:

   NM_DHCP_HELPER=/usr/libexec/nm-dhcp-helper
   nmcli general logging level TRACE
   for i in `seq 1 500`; do $NM_DHCP_HELPER & done
   journalctl -u NetworkManager --since '1 min ago' | grep "didn't have associated interface" | wc -l
    499

Avoid that, by calling the synchronous D-Bus method "Notify".

Interestingly, this race seem to exist since 2007.

Actually, we called g_dbus_connection_signal_subscribe() from inside
GDBusServer:new-connection signal. So it is not clear how such a race
could exist. I was not able to reproduce it by putting a sleep
before g_dbus_connection_signal_subscribe(). On the other hand, there
is bug rh#1372854 and above reproducer which strongly indicates that
events can be lost under certain circumstances.
Now we instead g_dbus_connection_register_object() from the
new-connection signal. According to my tests there was no more race
as also backed by glib's documentation. Still, keep a simple retry-loop
in nm-dhcp-helper just to be sure.

https://bugzilla.redhat.com/show_bug.cgi?id=1372854
https://bugzilla.redhat.com/show_bug.cgi?id=1373276
(cherry picked from commit 2856a658b38df88494187c811415a198a424e1f2)

4 files changed, 153 insertions, 33 deletions

diff --git a/src/dhcp-manager/nm-dhcp-helper-api.h b/src/dhcp-manager/nm-dhcp-helper-api.h
index a6323dbf58..a3eb171dc5 100644
--- a/src/dhcp-manager/nm-dhcp-helper-api.h
+++ b/src/dhcp-manager/nm-dhcp-helper-api.h
@@ -26,6 +26,11 @@
 
 #define NM_DHCP_CLIENT_DBUS_IFACE "org.freedesktop.nm_dhcp_client"
 
+#define NM_DHCP_HELPER_SERVER_BUS_NAME          "org.freedesktop.nm_dhcp_server"
+#define NM_DHCP_HELPER_SERVER_OBJECT_PATH       "/org/freedesktop/nm_dhcp_server"
+#define NM_DHCP_HELPER_SERVER_INTERFACE_NAME    "org.freedesktop.nm_dhcp_server"
+#define NM_DHCP_HELPER_SERVER_METHOD_NOTIFY     "Notify"
+
 /******************************************************************************/
 
 #endif /* __NM_DHCP_HELPER_API_H__ */
diff --git a/src/dhcp-manager/nm-dhcp-helper.c b/src/dhcp-manager/nm-dhcp-helper.c
index e467cfef05..cdbc740825 100644
--- a/src/dhcp-manager/nm-dhcp-helper.c
+++ b/src/dhcp-manager/nm-dhcp-helper.c
@@ -105,7 +105,7 @@ build_signal_parameters (void)
 		g_free (name);
 	}
 
-	return g_variant_new ("(a{sv})", &builder);
+	return g_variant_ref_sink (g_variant_new ("(a{sv})", &builder));
 }
 
 static void
@@ -128,7 +128,11 @@ main (int argc, char *argv[])
 {
 	gs_unref_object GDBusConnection *connection = NULL;
 	gs_free_error GError *error = NULL;
+	gs_unref_variant GVariant *parameters = NULL;
+	gs_unref_variant GVariant *result = NULL;
 	gboolean success = FALSE;
+	guint try_count = 0;
+	gint64 time_end;
 
 	nm_g_type_init ();
 
@@ -142,25 +146,73 @@ main (int argc, char *argv[])
 		goto out;
 	}
 
-	if (!g_dbus_connection_emit_signal (connection,
-	                                    NULL,
-	                                    "/",
-	                                    NM_DHCP_CLIENT_DBUS_IFACE,
-	                                    "Event",
-	                                    build_signal_parameters (),
-	                                    &error)) {
-		g_dbus_error_strip_remote_error (error);
-		_LOGE ("could not send DHCP Event signal: %s", error->message);
-		goto out;
-	}
+	parameters = build_signal_parameters ();
+
+	time_end = g_get_monotonic_time () + (200 * 1000L); /* retry for at most 200 milliseconds */
+
+do_notify:
+	try_count++;
+	result = g_dbus_connection_call_sync (connection,
+	                                      NULL,
+	                                      NM_DHCP_HELPER_SERVER_OBJECT_PATH,
+	                                      NM_DHCP_HELPER_SERVER_INTERFACE_NAME,
+	                                      NM_DHCP_HELPER_SERVER_METHOD_NOTIFY,
+	                                      parameters,
+	                                      NULL,
+	                                      G_DBUS_CALL_FLAGS_NONE,
+	                                      1000,
+	                                      NULL,
+	                                      &error);
+
+	if (!result) {
+		gs_free char *s_err = NULL;
+
+		s_err = g_dbus_error_get_remote_error (error);
+		if (NM_IN_STRSET (s_err, "org.freedesktop.DBus.Error.UnknownMethod")) {
+			gint64 remaining_time = time_end - g_get_monotonic_time ();
+
+			/* I am not sure that a race can actually happen, as we register the object
+			 * on the server side during GDBusServer:new-connection signal.
+			 *
+			 * However, there was also a race for subscribing to an event, so let's just
+			 * do some retry. */
+			if (remaining_time > 0) {
+				_LOGi ("failure to call notify: %s (retry %u)", error->message, try_count);
+				g_usleep (NM_MIN (NM_CLAMP ((gint64) (100L * (1L << try_count)), 5000, 25000), remaining_time));
+				g_clear_error (&error);
+				goto do_notify;
+			}
+		}
+		_LOGW ("failure to call notify: %s (try signal via Event)", error->message);
+		g_clear_error (&error);
+
+		/* for backward compatibilty, try to emit the signal. There is no stable
+		 * API between the dhcp-helper and NetworkManager. However, while upgrading
+		 * the NetworkManager package, a newer helper might want to notify an
+		 * older server, which still uses the "Event". */
+		if (!g_dbus_connection_emit_signal (connection,
+		                                    NULL,
+		                                    "/",
+		                                    NM_DHCP_CLIENT_DBUS_IFACE,
+		                                    "Event",
+		                                    parameters,
+		                                    &error)) {
+			g_dbus_error_strip_remote_error (error);
+			_LOGE ("could not send DHCP Event signal: %s", error->message);
+			goto out;
+		}
+		/* We were able to send the asynchronous Event. Consider that a success. */
+		success = TRUE;
+	} else
+		success = TRUE;
 
 	if (!g_dbus_connection_flush_sync (connection, NULL, &error)) {
 		g_dbus_error_strip_remote_error (error);
 		_LOGE ("could not flush D-Bus connection: %s", error->message);
+		success = FALSE;
 		goto out;
 	}
 
-	success = TRUE;
 out:
 	if (!success)
 		kill_pid ();
diff --git a/src/dhcp-manager/nm-dhcp-listener.c b/src/dhcp-manager/nm-dhcp-listener.c
index 7e9de49587..0df4197389 100644
--- a/src/dhcp-manager/nm-dhcp-listener.c
+++ b/src/dhcp-manager/nm-dhcp-listener.c
@@ -119,13 +119,14 @@ get_option (GVariant *options, const char *key)
 }
 
 static void
-handle_event (GDBusConnection  *connection,
-              const char       *sender_name,
-              const char       *object_path,
-              const char       *interface_name,
-              const char       *signal_name,
-              GVariant         *parameters,
-              gpointer          user_data)
+_method_call (GDBusConnection *connection,
+              const char *sender,
+              const char *object_path,
+              const char *interface_name,
+              const char *method_name,
+              GVariant *parameters,
+              GDBusMethodInvocation *invocation,
+              gpointer user_data)
 {
 	NMDhcpListener *self = NM_DHCP_LISTENER (user_data);
 	char *iface = NULL;
@@ -135,8 +136,12 @@ handle_event (GDBusConnection  *connection,
 	gboolean handled = FALSE;
 	GVariant *options;
 
+	if (!nm_streq0 (interface_name, NM_DHCP_HELPER_SERVER_INTERFACE_NAME))
+		g_return_if_reached ();
+	if (!nm_streq0 (method_name, NM_DHCP_HELPER_SERVER_METHOD_NOTIFY))
+		g_return_if_reached ();
 	if (!g_variant_is_of_type (parameters, G_VARIANT_TYPE ("(a{sv})")))
-		return;
+		g_return_if_reached ();
 
 	g_variant_get (parameters, "(@a{sv})", &options);
 
@@ -173,6 +178,57 @@ out:
 	g_free (pid_str);
 	g_free (reason);
 	g_variant_unref (options);
+	g_dbus_method_invocation_return_value (invocation, NULL);
+}
+
+static guint
+_dbus_connection_register_object (NMDhcpListener *self,
+                                  GDBusConnection *connection,
+                                  GError **error)
+{
+	static GDBusArgInfo arg_info_notify_in = {
+		.ref_count = -1,
+		.name = "data",
+		.signature = "a{sv}",
+		.annotations = NULL,
+	};
+	static GDBusArgInfo *arg_infos_notify[] = {
+		&arg_info_notify_in,
+		NULL,
+	};
+	static GDBusMethodInfo method_info_notify = {
+		.ref_count = -1,
+		.name = NM_DHCP_HELPER_SERVER_METHOD_NOTIFY,
+		.in_args = arg_infos_notify,
+		.out_args = NULL,
+		.annotations = NULL,
+	};
+	static GDBusMethodInfo *method_infos[] = {
+		&method_info_notify,
+		NULL,
+	};
+	static GDBusInterfaceInfo interface_info = {
+		.ref_count = -1,
+		.name = NM_DHCP_HELPER_SERVER_INTERFACE_NAME,
+		.methods = method_infos,
+		.signals = NULL,
+		.properties = NULL,
+		.annotations = NULL,
+	};
+
+	static GDBusInterfaceVTable interface_vtable = {
+		.method_call = _method_call,
+		.get_property = NULL,
+		.set_property = NULL,
+	};
+
+	return g_dbus_connection_register_object (connection,
+	                                          NM_DHCP_HELPER_SERVER_OBJECT_PATH,
+	                                          &interface_info,
+	                                          &interface_vtable,
+	                                          self,
+	                                          NULL,
+	                                          error);
 }
 
 static void
@@ -182,17 +238,20 @@ new_connection_cb (NMBusManager *mgr,
                    NMDhcpListener *self)
 {
 	NMDhcpListenerPrivate *priv = NM_DHCP_LISTENER_GET_PRIVATE (self);
-	guint id;
+	guint registration_id;
+	GError *error = NULL;
+
+	/* it is important to register the object during the new-connection signal,
+	 * as this avoids races with the connecting object. */
+	registration_id = _dbus_connection_register_object (self, connection, &error);
+	if (!registration_id) {
+		_LOGE ("failure to register %s for connection %p: %s",
+		       NM_DHCP_HELPER_SERVER_OBJECT_PATH, connection, error->message);
+		g_error_free (error);
+		return;
+	}
 
-	id = g_dbus_connection_signal_subscribe (connection,
-	                                         NULL,
-	                                         NM_DHCP_CLIENT_DBUS_IFACE,
-	                                         "Event",
-	                                         NULL,
-	                                         NULL,
-	                                         G_DBUS_SIGNAL_FLAGS_NONE,
-	                                         handle_event, self, NULL);
-	g_hash_table_insert (priv->connections, connection, GUINT_TO_POINTER (id));
+	g_hash_table_insert (priv->connections, connection, GUINT_TO_POINTER (registration_id));
 }
 
 static void
@@ -205,7 +264,7 @@ dis_connection_cb (NMBusManager *mgr,
 
 	id = GPOINTER_TO_UINT (g_hash_table_lookup (priv->connections, connection));
 	if (id) {
-		g_dbus_connection_signal_unsubscribe (connection, id);
+		g_dbus_connection_unregister_object (connection, id);
 		g_hash_table_remove (priv->connections, connection);
 	}
 }
diff --git a/src/nm-bus-manager.c b/src/nm-bus-manager.c
index 656e7dbf6b..699df546fd 100644
--- a/src/nm-bus-manager.c
+++ b/src/nm-bus-manager.c
@@ -221,7 +221,11 @@ private_server_new_connection (GDBusServer *server,
 
 	_LOGD ("(%s) accepted connection %p on private socket", s->tag, conn);
 
-	/* Emit this for the manager */
+	/* Emit this for the manager.
+	 *
+	 * It is essential to do this from the "new-connection" signal handler, as
+	 * at that point no messages from the connection are yet processed
+	 * (which avoids races with registering objects). */
 	g_signal_emit (s->manager,
 	               signals[PRIVATE_CONNECTION_NEW],
 	               s->detail,