From 2e2e588cd515e9d928091321887c720f3311158b Mon Sep 17 00:00:00 2001
From: Beniamino Galvani <bgalvani@redhat.com>
Date: Thu, 16 Jul 2015 09:23:52 +0200
Subject: [PATCH 1/8] nm-dispatcher: fix memory leaks

---
 callouts/nm-dispatcher.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/callouts/nm-dispatcher.c b/callouts/nm-dispatcher.c
index 3cb50b5790..5349089cea 100644
--- a/callouts/nm-dispatcher.c
+++ b/callouts/nm-dispatcher.c
@@ -145,6 +145,7 @@ request_free (Request *request)
 	g_strfreev (request->envp);
 	if (request->scripts)
 		g_ptr_array_free (request->scripts, TRUE);
+	g_free (request);
 }
 
 static gboolean
@@ -514,7 +515,7 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 		g_message ("\n");
 	}
 
-	request->iface = g_strdup (iface);
+	request->iface = iface;
 
 	request->scripts = g_ptr_array_new_full (5, script_info_free);
 	for (iter = sorted_scripts; iter; iter = g_slist_next (iter)) {

From 1999723241c49a7f2d5052d34299aad3d6e26e41 Mon Sep 17 00:00:00 2001
From: Beniamino Galvani <bgalvani@redhat.com>
Date: Tue, 14 Jul 2015 18:17:33 +0200
Subject: [PATCH 2/8] nm-dispatcher: allow scripts to be marked as no-wait

When a script is a symbolic link to the 'no-wait.d' subdirectory, the
dispatcher now schedules it immediately and in parallel with other
no-wait scripts.

https://bugzilla.gnome.org/show_bug.cgi?id=746703
---
 callouts/Makefile.am                   |   1 +
 callouts/nm-dispatcher-api.h           |   1 +
 callouts/nm-dispatcher.c               | 312 +++++++++++++++++++------
 contrib/fedora/rpm/NetworkManager.spec |   2 +
 man/NetworkManager.xml                 |  10 +-
 5 files changed, 249 insertions(+), 77 deletions(-)

diff --git a/callouts/Makefile.am b/callouts/Makefile.am
index 1f89356fa3..a2d574c66b 100644
--- a/callouts/Makefile.am
+++ b/callouts/Makefile.am
@@ -94,6 +94,7 @@ install-data-hook:
 	   $(mkinstalldirs) -m 0755 $(DESTDIR)$(dispatcherdir)
 	   $(mkinstalldirs) -m 0755 $(DESTDIR)$(dispatcherdir)/pre-down.d
 	   $(mkinstalldirs) -m 0755 $(DESTDIR)$(dispatcherdir)/pre-up.d
+	   $(mkinstalldirs) -m 0755 $(DESTDIR)$(dispatcherdir)/no-wait.d
 
 CLEANFILES = $(nodist_libnmdbus_dispatcher_la_SOURCES) $(dbusactivation_DATA)
 
diff --git a/callouts/nm-dispatcher-api.h b/callouts/nm-dispatcher-api.h
index e84b08f489..d702ba6851 100644
--- a/callouts/nm-dispatcher-api.h
+++ b/callouts/nm-dispatcher-api.h
@@ -21,6 +21,7 @@
 #define NMD_SCRIPT_DIR_DEFAULT  NMCONFDIR "/dispatcher.d"
 #define NMD_SCRIPT_DIR_PRE_UP   NMD_SCRIPT_DIR_DEFAULT "/pre-up.d"
 #define NMD_SCRIPT_DIR_PRE_DOWN NMD_SCRIPT_DIR_DEFAULT "/pre-down.d"
+#define NMD_SCRIPT_DIR_NO_WAIT  NMD_SCRIPT_DIR_DEFAULT "/no-wait.d"
 
 #define NM_DISPATCHER_DBUS_SERVICE   "org.freedesktop.nm_dispatcher"
 #define NM_DISPATCHER_DBUS_INTERFACE "org.freedesktop.nm_dispatcher"
diff --git a/callouts/nm-dispatcher.c b/callouts/nm-dispatcher.c
index 5349089cea..eb136a75fb 100644
--- a/callouts/nm-dispatcher.c
+++ b/callouts/nm-dispatcher.c
@@ -37,6 +37,8 @@
 #include "nm-default.h"
 #include "nm-dispatcher-api.h"
 #include "nm-dispatcher-utils.h"
+#include "nm-macros-internal.h"
+#include "gsystem-local-alloc.h"
 
 #include "nmdbus-dispatcher.h"
 
@@ -54,7 +56,8 @@ typedef struct {
 	NMDBusDispatcher *dbus_dispatcher;
 
 	Request *current_request;
-	GQueue *pending_requests;
+	GQueue *requests_waiting;
+	gint num_requests_pending;
 } Handler;
 
 typedef struct {
@@ -89,7 +92,7 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 static void
 handler_init (Handler *h)
 {
-	h->pending_requests = g_queue_new ();
+	h->requests_waiting = g_queue_new ();
 	h->dbus_dispatcher = nmdbus_dispatcher_skeleton_new ();
 	g_signal_connect (h->dbus_dispatcher, "handle-action",
 	                  G_CALLBACK (handle_action), h);
@@ -100,7 +103,7 @@ handler_class_init (HandlerClass *h_class)
 {
 }
 
-static void dispatch_one_script (Request *request);
+static gboolean dispatch_one_script (Request *request);
 
 typedef struct {
 	Request *request;
@@ -109,6 +112,10 @@ typedef struct {
 	GPid pid;
 	DispatchResult result;
 	char *error;
+	gboolean wait;
+	gboolean dispatched;
+	guint watch_id;
+	guint timeout_id;
 } ScriptInfo;
 
 struct Request {
@@ -122,9 +129,7 @@ struct Request {
 
 	GPtrArray *scripts;  /* list of ScriptInfo */
 	guint idx;
-
-	guint script_watch_id;
-	guint script_timeout_id;
+	gint num_scripts_done;
 };
 
 static void
@@ -140,11 +145,14 @@ script_info_free (gpointer ptr)
 static void
 request_free (Request *request)
 {
+	g_assert_cmpuint (request->num_scripts_done, ==, request->scripts->len);
+
 	g_free (request->action);
 	g_free (request->iface);
 	g_strfreev (request->envp);
 	if (request->scripts)
 		g_ptr_array_free (request->scripts, TRUE);
+
 	g_free (request);
 }
 
@@ -156,64 +164,81 @@ quit_timeout_cb (gpointer user_data)
 }
 
 static void
-quit_timeout_cancel (void)
+quit_timeout_reschedule (void)
 {
-	if (quit_id) {
-		g_source_remove (quit_id);
-		quit_id = 0;
+	if (!persist) {
+		nm_clear_g_source (&quit_id);
+		quit_id = g_timeout_add_seconds (10, quit_timeout_cb, NULL);
 	}
 }
 
-static void
-quit_timeout_reschedule (void)
+/**
+ * next_request:
+ *
+ * @h: the handler
+ * @request: (allow-none): the request to set as next. If %NULL, dequeue the next
+ * waiting request. Otherwise, try to set the given request.
+ *
+ * Sets the currently active request (@current_request). The current request
+ * is a request that has at least on "wait" script, because requests that only
+ * consist of "no-wait" scripts are handled right away and not enqueued to
+ * @requests_waiting nor set as @current_request.
+ *
+ * Returns: %TRUE, if there was currently not request in process and it set
+ * a new request as current.
+ */
+static gboolean
+next_request (Handler *h, Request *request)
 {
-	quit_timeout_cancel ();
-	if (!persist)
-		quit_id = g_timeout_add_seconds (10, quit_timeout_cb, NULL);
-}
+	if (request) {
+		if (h->current_request) {
+			g_queue_push_tail (h->requests_waiting, request);
+			return FALSE;
+		}
+	} else {
+		/* when calling next_request() without explicit @request, we always
+		 * forcefully clear @current_request. That one is certainly
+		 * handled already. */
+		h->current_request = NULL;
+
+		request = g_queue_pop_head (h->requests_waiting);
+		if (!request)
+			return FALSE;
+	}
 
-static void
-start_request (Request *request)
-{
 	if (request->iface)
 		g_message ("Dispatching action '%s' for %s", request->action, request->iface);
 	else
 		g_message ("Dispatching action '%s'", request->action);
 
-	request->handler->current_request = request;
-	dispatch_one_script (request);
+	h->current_request = request;
+
+	return TRUE;
 }
 
+/**
+ * complete_request:
+ * @request: the request
+ *
+ * Checks if all the scripts for the request have terminated and in such case
+ * it sends the D-Bus response and releases the request resources.
+ *
+ * It also decreases @num_requests_pending and possibly does quit_timeout_reschedule().
+ */
 static void
-next_request (Handler *h)
+complete_request (Request *request)
 {
-	Request *request = g_queue_pop_head (h->pending_requests);
-
-	if (request) {
-		start_request (request);
-		return;
-	}
-
-	h->current_request = NULL;
-	quit_timeout_reschedule ();
-}
-
-static gboolean
-next_script (gpointer user_data)
-{
-	Request *request = user_data;
-	Handler *h = request->handler;
 	GVariantBuilder results;
 	GVariant *ret;
 	guint i;
+	Handler *handler = request->handler;
 
-	request->idx++;
-	if (request->idx < request->scripts->len) {
-		dispatch_one_script (request);
-		return FALSE;
-	}
+	nm_assert (request);
+
+	/* Are there still pending scripts? Then do nothing (for now). */
+	if (request->num_scripts_done < request->scripts->len)
+		return;
 
-	/* All done */
 	g_variant_builder_init (&results, G_VARIANT_TYPE ("a(sus)"));
 	for (i = 0; i < request->scripts->len; i++) {
 		ScriptInfo *script = g_ptr_array_index (request->scripts, i);
@@ -233,10 +258,63 @@ next_script (gpointer user_data)
 		else
 			g_message ("Dispatch '%s' complete", request->action);
 	}
+
+	if (handler->current_request == request)
+		handler->current_request = NULL;
+
 	request_free (request);
 
-	next_request (h);
-	return FALSE;
+	g_assert_cmpuint (handler->num_requests_pending, >, 0);
+	if (--handler->num_requests_pending <= 0) {
+		nm_assert (!handler->current_request && !g_queue_peek_head (handler->requests_waiting));
+		quit_timeout_reschedule ();
+	}
+}
+
+static void
+complete_script (ScriptInfo *script)
+{
+	Handler *handler;
+	gboolean wait = script->wait;
+
+	if (wait) {
+		/* for "wait" scripts, try to schedule the next blocking script.
+		 * If that is successful, return (as we must wait for its completion). */
+		if (dispatch_one_script (script->request))
+			return;
+	}
+
+	handler = script->request->handler;
+
+	nm_assert (!wait || handler->current_request == script->request);
+
+	/* Try to complete the request. */
+	complete_request (script->request);
+
+	if (!wait) {
+		/* this was a "no-wait" script. We either completed the request,
+		 * or there is nothing to do. Especially, there is no need to
+		 * queue the next_request() -- because no-wait scripts don't block
+		 * requests. */
+		return;
+	}
+
+	while (next_request (handler, NULL)) {
+		Request *request;
+
+		request = handler->current_request;
+
+		if (dispatch_one_script (request))
+			return;
+
+		/* Try to complete the request. It will be either completed
+		 * now, or when all pending "no-wait" scripts return. */
+		complete_request (request);
+
+		/* We can immediately start next_request(), because our current
+		 * @request has obviously no more "wait" scripts either.
+		 * Repeat... */
+	}
 }
 
 static void
@@ -247,9 +325,9 @@ script_watch_cb (GPid pid, gint status, gpointer user_data)
 
 	g_assert (pid == script->pid);
 
-	script->request->script_watch_id = 0;
-	g_source_remove (script->request->script_timeout_id);
-	script->request->script_timeout_id = 0;
+	script->watch_id = 0;
+	nm_clear_g_source (&script->timeout_id);
+	script->request->num_scripts_done++;
 
 	if (WIFEXITED (status)) {
 		err = WEXITSTATUS (status);
@@ -279,7 +357,8 @@ script_watch_cb (GPid pid, gint status, gpointer user_data)
 	}
 
 	g_spawn_close_pid (script->pid);
-	next_script (script->request);
+
+	complete_script (script);
 }
 
 static gboolean
@@ -287,9 +366,9 @@ script_timeout_cb (gpointer user_data)
 {
 	ScriptInfo *script = user_data;
 
-	g_source_remove (script->request->script_watch_id);
-	script->request->script_watch_id = 0;
-	script->request->script_timeout_id = 0;
+	script->timeout_id = 0;
+	nm_clear_g_source (&script->watch_id);
+	script->request->num_scripts_done++;
 
 	g_warning ("Script '%s' took too long; killing it.", script->script);
 
@@ -304,7 +383,9 @@ again:
 	script->result = DISPATCH_RESULT_TIMEOUT;
 
 	g_spawn_close_pid (script->pid);
-	g_idle_add (next_script, script->request);
+
+	complete_script (script);
+
 	return FALSE;
 }
 
@@ -365,12 +446,17 @@ check_filename (const char *file_name)
 
 #define SCRIPT_TIMEOUT 600  /* 10 minutes */
 
-static void
-dispatch_one_script (Request *request)
+static gboolean
+script_dispatch (ScriptInfo *script)
 {
 	GError *error = NULL;
 	gchar *argv[4];
-	ScriptInfo *script = g_ptr_array_index (request->scripts, request->idx);
+	Request *request = script->request;
+
+	if (script->dispatched)
+		return FALSE;
+
+	script->dispatched = TRUE;
 
 	argv[0] = script->script;
 	argv[1] = request->iface
@@ -382,21 +468,34 @@ dispatch_one_script (Request *request)
 	if (request->debug)
 		g_message ("Running script '%s'", script->script);
 
-	if (g_spawn_async ("/", argv, request->envp, G_SPAWN_DO_NOT_REAP_CHILD, NULL, request, &script->pid, &error)) {
-		request->script_watch_id = g_child_watch_add (script->pid, (GChildWatchFunc) script_watch_cb, script);
-		request->script_timeout_id = g_timeout_add_seconds (SCRIPT_TIMEOUT, script_timeout_cb, script);
+	if (g_spawn_async ("/", argv, request->envp, G_SPAWN_DO_NOT_REAP_CHILD, NULL, NULL, &script->pid, &error)) {
+		script->watch_id = g_child_watch_add (script->pid, (GChildWatchFunc) script_watch_cb, script);
+		script->timeout_id = g_timeout_add_seconds (SCRIPT_TIMEOUT, script_timeout_cb, script);
+		return TRUE;
 	} else {
 		g_warning ("Failed to execute script '%s': (%d) %s",
 		           script->script, error->code, error->message);
 		script->result = DISPATCH_RESULT_EXEC_FAILED;
 		script->error = g_strdup (error->message);
+		request->num_scripts_done++;
 		g_clear_error (&error);
-
-		/* Try the next script */
-		g_idle_add (next_script, request);
+		return FALSE;
 	}
 }
 
+static gboolean
+dispatch_one_script (Request *request)
+{
+	while (request->idx < request->scripts->len) {
+		ScriptInfo *script;
+
+		script = g_ptr_array_index (request->scripts, request->idx++);
+		if (script_dispatch (script))
+			return TRUE;
+	}
+	return FALSE;
+}
+
 static GSList *
 find_scripts (const char *str_action)
 {
@@ -452,6 +551,34 @@ find_scripts (const char *str_action)
 	return sorted;
 }
 
+static gboolean
+script_must_wait (const char *path)
+{
+	gs_free char *link = NULL;
+	gs_free char *dir = NULL;
+	gs_free char *real = NULL;
+	char *tmp;
+
+	link = g_file_read_link (path, NULL);
+	if (link) {
+		if (!g_path_is_absolute (link)) {
+			dir = g_path_get_dirname (path);
+			tmp = g_build_path ("/", dir, link, NULL);
+			g_free (link);
+			g_free (dir);
+			link = tmp;
+		}
+
+		dir = g_path_get_dirname (link);
+		real = realpath (dir, NULL);
+
+		if (real && !strcmp (real, NMD_SCRIPT_DIR_NO_WAIT))
+			return FALSE;
+	}
+
+	return TRUE;
+}
+
 static gboolean
 handle_action (NMDBusDispatcher *dbus_dispatcher,
                GDBusMethodInvocation *context,
@@ -475,6 +602,7 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 	Request *request;
 	char **p;
 	char *iface = NULL;
+	guint i, num_nowait = 0;
 
 	sorted_scripts = find_scripts (str_action);
 
@@ -486,7 +614,7 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 		return TRUE;
 	}
 
-	quit_timeout_cancel ();
+	nm_clear_g_source (&quit_id);
 
 	request = g_malloc0 (sizeof (*request));
 	request->handler = h;
@@ -522,14 +650,53 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 		ScriptInfo *s = g_malloc0 (sizeof (*s));
 		s->request = request;
 		s->script = iter->data;
+		s->wait = script_must_wait (s->script);
 		g_ptr_array_add (request->scripts, s);
 	}
 	g_slist_free (sorted_scripts);
+	h->num_requests_pending++;
 
-	if (h->current_request)
-		g_queue_push_tail (h->pending_requests, request);
-	else
-		start_request (request);
+	for (i = 0; i < request->scripts->len; i++) {
+		ScriptInfo *s = g_ptr_array_index (request->scripts, i);
+
+		if (!s->wait) {
+			script_dispatch (s);
+			num_nowait++;
+		}
+	}
+
+	if (num_nowait < request->scripts->len) {
+		/* The request has at least one wait script.
+		 * Try next_request() to schedule the request for
+		 * execution. This either enqueues the request or
+		 * sets it as h->current_request. */
+		if (next_request (h, request)) {
+			/* @request is now @current_request. Go ahead and
+			 * schedule the first wait script. */
+			if (!dispatch_one_script (request)) {
+				/* If that fails, we might be already finished with the
+				 * request. Try complete_request(). */
+				complete_request (request);
+
+				if (next_request (h, NULL)) {
+					/* As @request was successfully scheduled as next_request(), there is no
+					 * other request in queue that can be scheduled afterwards. Assert against
+					 * that, but call next_request() to clear current_request. */
+					g_assert_not_reached ();
+				}
+			}
+		}
+	} else {
+		/* The request contains only no-wait scripts. Try to complete
+		 * the request right away (we might have failed to schedule any
+		 * of the scripts). It will be either completed now, or later
+		 * when the pending scripts return.
+		 * We don't enqueue it to h->requests_waiting.
+		 * There is no need to handle next_request(), because @request is
+		 * not the current request anyway and does not interfere with requests
+		 * that have any "wait" scripts. */
+		complete_request (request);
+	}
 
 	return TRUE;
 }
@@ -572,7 +739,7 @@ log_handler (const gchar *log_domain,
              const gchar *message,
              gpointer ignored)
 {
-	int syslog_priority;	
+	int syslog_priority;
 
 	switch (log_level) {
 	case G_LOG_LEVEL_ERROR:
@@ -604,7 +771,7 @@ static void
 logging_setup (void)
 {
 	openlog (G_LOG_DOMAIN, LOG_CONS, LOG_DAEMON);
-	g_log_set_handler (G_LOG_DOMAIN, 
+	g_log_set_handler (G_LOG_DOMAIN,
 	                   G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION,
 	                   log_handler,
 	                   NULL);
@@ -690,12 +857,11 @@ main (int argc, char **argv)
 	                              NULL, NULL);
 	g_object_unref (bus);
 
-	if (!persist)
-		quit_id = g_timeout_add_seconds (10, quit_timeout_cb, NULL);
+	quit_timeout_reschedule ();
 
 	g_main_loop_run (loop);
 
-	g_queue_free (handler->pending_requests);
+	g_queue_free (handler->requests_waiting);
 	g_object_unref (handler);
 
 	if (!debug)
diff --git a/contrib/fedora/rpm/NetworkManager.spec b/contrib/fedora/rpm/NetworkManager.spec
index 4e4df5475e..538ef2d87d 100644
--- a/contrib/fedora/rpm/NetworkManager.spec
+++ b/contrib/fedora/rpm/NetworkManager.spec
@@ -459,6 +459,7 @@ mkdir -p $RPM_BUILD_ROOT%{nmlibdir}/VPN
 mkdir -p $RPM_BUILD_ROOT%{_sysconfdir}/%{name}/dispatcher.d
 mkdir -p $RPM_BUILD_ROOT%{_sysconfdir}/%{name}/dispatcher.d/pre-up.d
 mkdir -p $RPM_BUILD_ROOT%{_sysconfdir}/%{name}/dispatcher.d/pre-down.d
+mkdir -p $RPM_BUILD_ROOT%{_sysconfdir}/%{name}/dispatcher.d/no-wait.d
 %{__cp} examples/dispatcher/10-ifcfg-rh-routes.sh $RPM_BUILD_ROOT%{_sysconfdir}/%{name}/dispatcher.d/
 %{__ln_s} ../10-ifcfg-rh-routes.sh $RPM_BUILD_ROOT%{_sysconfdir}/%{name}/dispatcher.d/pre-up.d/
 
@@ -527,6 +528,7 @@ fi
 %{_sysconfdir}/%{name}/dispatcher.d/10-ifcfg-rh-routes.sh
 %dir %{_sysconfdir}/%{name}/dispatcher.d/pre-down.d
 %dir %{_sysconfdir}/%{name}/dispatcher.d/pre-up.d
+%dir %{_sysconfdir}/%{name}/dispatcher.d/no-wait.d
 %{_sysconfdir}/%{name}/dispatcher.d/pre-up.d/10-ifcfg-rh-routes.sh
 %dir %{_sysconfdir}/%{name}/dnsmasq.d
 %dir %{_sysconfdir}/%{name}/VPN
diff --git a/man/NetworkManager.xml b/man/NetworkManager.xml
index 38cfe4e288..f31e4b6fa7 100644
--- a/man/NetworkManager.xml
+++ b/man/NetworkManager.xml
@@ -270,10 +270,12 @@
       Dispatcher scripts are run one at a time, but asynchronously from the main
       NetworkManager process, and will be killed if they run for too long. If your script
       might take arbitrarily long to complete, you should spawn a child process and have the
-      parent return immediately. Also beware that once a script is queued, it will always be
-      run, even if a later event renders it obsolete. (Eg, if an interface goes up, and then
-      back down again quickly, it is possible that one or more "up" scripts will be run
-      after the interface has gone down.)
+      parent return immediately. Scripts that are symbolic links pointing inside the
+      /etc/NetworkManager/dispatcher.d/no-wait.d/ directory are run immediately, without
+      waiting for the termination of previous scripts, and in parallel. Also beware that
+      once a script is queued, it will always be run, even if a later event renders it
+      obsolete. (Eg, if an interface goes up, and then back down again quickly, it is
+      possible that one or more "up" scripts will be run after the interface has gone down.)
     </para>
   </refsect1>
 

From e97a334e375b936ac66864e6d69ffe75ffa22aa9 Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Mon, 27 Jul 2015 22:44:56 +0200
Subject: [PATCH 3/8] dispatcher: run "wait" scripts only after "no-wait"
 scripts complete

Previously, dispatcher would start all "no-wait" script right away,
but it would also start the first "wait" script while the "no-wait"
script are still running (unless, there are other "wait" scripts that
delay the execution).

Now, do not start processing the "wait" scripts, as long as there are
any "no-wait" scripts from the same request running.
---
 callouts/nm-dispatcher.c | 25 +++++++++++++++++++++++--
 1 file changed, 23 insertions(+), 2 deletions(-)

diff --git a/callouts/nm-dispatcher.c b/callouts/nm-dispatcher.c
index eb136a75fb..0999b1944f 100644
--- a/callouts/nm-dispatcher.c
+++ b/callouts/nm-dispatcher.c
@@ -130,6 +130,7 @@ struct Request {
 	GPtrArray *scripts;  /* list of ScriptInfo */
 	guint idx;
 	gint num_scripts_done;
+	gint num_scripts_nowait;
 };
 
 static void
@@ -146,6 +147,7 @@ static void
 request_free (Request *request)
 {
 	g_assert_cmpuint (request->num_scripts_done, ==, request->scripts->len);
+	g_assert_cmpuint (request->num_scripts_nowait, ==, 0);
 
 	g_free (request->action);
 	g_free (request->iface);
@@ -295,8 +297,18 @@ complete_script (ScriptInfo *script)
 		/* this was a "no-wait" script. We either completed the request,
 		 * or there is nothing to do. Especially, there is no need to
 		 * queue the next_request() -- because no-wait scripts don't block
-		 * requests. */
-		return;
+		 * requests. However, if this was the last "no-wait" script and
+		 * there are "wait" scripts ready to run, launch them.
+		 */
+		if (   script->request->num_scripts_nowait == 0
+		    && handler->current_request == script->request) {
+
+			if (dispatch_one_script (script->request))
+				return;
+
+			complete_request (script->request);
+		} else
+			return;
 	}
 
 	while (next_request (handler, NULL)) {
@@ -328,6 +340,8 @@ script_watch_cb (GPid pid, gint status, gpointer user_data)
 	script->watch_id = 0;
 	nm_clear_g_source (&script->timeout_id);
 	script->request->num_scripts_done++;
+	if (!script->wait)
+		script->request->num_scripts_nowait--;
 
 	if (WIFEXITED (status)) {
 		err = WEXITSTATUS (status);
@@ -369,6 +383,8 @@ script_timeout_cb (gpointer user_data)
 	script->timeout_id = 0;
 	nm_clear_g_source (&script->watch_id);
 	script->request->num_scripts_done++;
+	if (!script->wait)
+		script->request->num_scripts_nowait--;
 
 	g_warning ("Script '%s' took too long; killing it.", script->script);
 
@@ -471,6 +487,8 @@ script_dispatch (ScriptInfo *script)
 	if (g_spawn_async ("/", argv, request->envp, G_SPAWN_DO_NOT_REAP_CHILD, NULL, NULL, &script->pid, &error)) {
 		script->watch_id = g_child_watch_add (script->pid, (GChildWatchFunc) script_watch_cb, script);
 		script->timeout_id = g_timeout_add_seconds (SCRIPT_TIMEOUT, script_timeout_cb, script);
+		if (!script->wait)
+			request->num_scripts_nowait++;
 		return TRUE;
 	} else {
 		g_warning ("Failed to execute script '%s': (%d) %s",
@@ -486,6 +504,9 @@ script_dispatch (ScriptInfo *script)
 static gboolean
 dispatch_one_script (Request *request)
 {
+	if (request->num_scripts_nowait > 0)
+		return TRUE;
+
 	while (request->idx < request->scripts->len) {
 		ScriptInfo *script;
 

From 8143d895ca65f71aee71e65168a74fe1a4f21100 Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Mon, 3 Aug 2015 16:15:25 +0200
Subject: [PATCH 4/8] dispatcher: use slice allocator for Request and
 ScriptInfo

---
 callouts/nm-dispatcher.c | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

diff --git a/callouts/nm-dispatcher.c b/callouts/nm-dispatcher.c
index 0999b1944f..98f61867a0 100644
--- a/callouts/nm-dispatcher.c
+++ b/callouts/nm-dispatcher.c
@@ -140,7 +140,7 @@ script_info_free (gpointer ptr)
 
 	g_free (info->script);
 	g_free (info->error);
-	g_free (info);
+	g_slice_free (ScriptInfo, info);
 }
 
 static void
@@ -155,7 +155,7 @@ request_free (Request *request)
 	if (request->scripts)
 		g_ptr_array_free (request->scripts, TRUE);
 
-	g_free (request);
+	g_slice_free (Request, request);
 }
 
 static gboolean
@@ -637,7 +637,7 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 
 	nm_clear_g_source (&quit_id);
 
-	request = g_malloc0 (sizeof (*request));
+	request = g_slice_new0 (Request);
 	request->handler = h;
 	request->debug = request_debug || debug;
 	request->context = context;
@@ -668,7 +668,9 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 
 	request->scripts = g_ptr_array_new_full (5, script_info_free);
 	for (iter = sorted_scripts; iter; iter = g_slist_next (iter)) {
-		ScriptInfo *s = g_malloc0 (sizeof (*s));
+		ScriptInfo *s;
+
+		s = g_slice_new0 (ScriptInfo);
 		s->request = request;
 		s->script = iter->data;
 		s->wait = script_must_wait (s->script);

From 38fa197bab78d0dcef372f25b64720d294a28be6 Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Mon, 3 Aug 2015 16:17:34 +0200
Subject: [PATCH 5/8] dispatcher: move clearing @quit_id in handle_action()

First create and initialize @request, and then start it.
---
 callouts/nm-dispatcher.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/callouts/nm-dispatcher.c b/callouts/nm-dispatcher.c
index 98f61867a0..cab2ba1098 100644
--- a/callouts/nm-dispatcher.c
+++ b/callouts/nm-dispatcher.c
@@ -635,8 +635,6 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 		return TRUE;
 	}
 
-	nm_clear_g_source (&quit_id);
-
 	request = g_slice_new0 (Request);
 	request->handler = h;
 	request->debug = request_debug || debug;
@@ -677,6 +675,9 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 		g_ptr_array_add (request->scripts, s);
 	}
 	g_slist_free (sorted_scripts);
+
+	nm_clear_g_source (&quit_id);
+
 	h->num_requests_pending++;
 
 	for (i = 0; i < request->scripts->len; i++) {

From 199754a845594430364d579b1bcc5dee2f33db5b Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Tue, 4 Aug 2015 10:49:54 +0200
Subject: [PATCH 6/8] dispatcher: remove local @iface variable from
 handle_action()

---
 callouts/nm-dispatcher.c | 7 ++-----
 1 file changed, 2 insertions(+), 5 deletions(-)

diff --git a/callouts/nm-dispatcher.c b/callouts/nm-dispatcher.c
index cab2ba1098..c769a8042d 100644
--- a/callouts/nm-dispatcher.c
+++ b/callouts/nm-dispatcher.c
@@ -622,7 +622,6 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 	GSList *iter;
 	Request *request;
 	char **p;
-	char *iface = NULL;
 	guint i, num_nowait = 0;
 
 	sorted_scripts = find_scripts (str_action);
@@ -652,18 +651,16 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 	                                                    vpn_ip_iface,
 	                                                    vpn_ip4_props,
 	                                                    vpn_ip6_props,
-	                                                    &iface);
+	                                                    &request->iface);
 
 	if (request->debug) {
 		g_message ("------------ Action ID %p '%s' Interface %s Environment ------------",
-		           context, str_action, iface ? iface : "(none)");
+		           context, str_action, request->iface ? request->iface : "(none)");
 		for (p = request->envp; *p; p++)
 			g_message ("  %s", *p);
 		g_message ("\n");
 	}
 
-	request->iface = iface;
-
 	request->scripts = g_ptr_array_new_full (5, script_info_free);
 	for (iter = sorted_scripts; iter; iter = g_slist_next (iter)) {
 		ScriptInfo *s;

From e81ba7594956f116b41c5a602269a0659435c433 Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Tue, 4 Aug 2015 10:51:32 +0200
Subject: [PATCH 7/8] dispatcher: return error reason from
 nm_dispatcher_utils_construct_envp()

Also, error out in handle_action() when nm_dispatcher_utils_construct_envp()
indicates a failure.
---
 callouts/nm-dispatcher-utils.c        | 26 ++++++++++++++++----------
 callouts/nm-dispatcher-utils.h        |  3 ++-
 callouts/nm-dispatcher.c              | 16 +++++++++++++++-
 callouts/tests/test-dispatcher-envp.c |  9 ++++++++-
 4 files changed, 41 insertions(+), 13 deletions(-)

diff --git a/callouts/nm-dispatcher-utils.c b/callouts/nm-dispatcher-utils.c
index bbd0e49016..6079d01969 100644
--- a/callouts/nm-dispatcher-utils.c
+++ b/callouts/nm-dispatcher-utils.c
@@ -331,7 +331,8 @@ nm_dispatcher_utils_construct_envp (const char *action,
                                     const char *vpn_ip_iface,
                                     GVariant *vpn_ip4_props,
                                     GVariant *vpn_ip6_props,
-                                    char **out_iface)
+                                    char **out_iface,
+                                    const char **out_error_message)
 {
 	const char *iface = NULL, *ip_iface = NULL;
 	const char *uuid = NULL, *id = NULL, *path = NULL;
@@ -343,6 +344,10 @@ nm_dispatcher_utils_construct_envp (const char *action,
 	GSList *items = NULL, *iter;
 	guint i;
 	GVariant *con_setting;
+	const char *error_message_backup;
+
+	if (!out_error_message)
+		out_error_message = &error_message_backup;
 
 	g_return_val_if_fail (action != NULL, NULL);
 	g_return_val_if_fail (out_iface != NULL, NULL);
@@ -354,7 +359,7 @@ nm_dispatcher_utils_construct_envp (const char *action,
 
 	/* Connection properties */
 	if (!g_variant_lookup (connection_props, NMD_CONNECTION_PROPS_PATH, "&o", &path)) {
-		g_warning ("Missing or invalid required value " NMD_CONNECTION_PROPS_PATH "!");
+		*out_error_message = "Missing or invalid required value " NMD_CONNECTION_PROPS_PATH "!";
 		return NULL;
 	}
 	items = g_slist_prepend (items, g_strdup_printf ("CONNECTION_DBUS_PATH=%s", path));
@@ -374,7 +379,7 @@ nm_dispatcher_utils_construct_envp (const char *action,
 
 	/* interface name */
 	if (!g_variant_lookup (device_props, NMD_DEVICE_PROPS_INTERFACE, "&s", &iface)) {
-		g_warning ("Missing or invalid required value " NMD_DEVICE_PROPS_INTERFACE "!");
+		*out_error_message = "Missing or invalid required value " NMD_DEVICE_PROPS_INTERFACE "!";
 		return NULL;
 	}
 	if (!*iface)
@@ -384,7 +389,7 @@ nm_dispatcher_utils_construct_envp (const char *action,
 	value = g_variant_lookup_value (device_props, NMD_DEVICE_PROPS_IP_INTERFACE, NULL);
 	if (value) {
 		if (!g_variant_is_of_type (value, G_VARIANT_TYPE_STRING)) {
-			g_warning ("Invalid value " NMD_DEVICE_PROPS_IP_INTERFACE "!");
+			*out_error_message = "Invalid value " NMD_DEVICE_PROPS_IP_INTERFACE "!";
 			return NULL;
 		}
 		g_variant_unref (value);
@@ -393,14 +398,14 @@ nm_dispatcher_utils_construct_envp (const char *action,
 
 	/* Device type */
 	if (!g_variant_lookup (device_props, NMD_DEVICE_PROPS_TYPE, "u", NULL)) {
-		g_warning ("Missing or invalid required value " NMD_DEVICE_PROPS_TYPE "!");
+		*out_error_message = "Missing or invalid required value " NMD_DEVICE_PROPS_TYPE "!";
 		return NULL;
 	}
 
 	/* Device state */
 	value = g_variant_lookup_value (device_props, NMD_DEVICE_PROPS_STATE, G_VARIANT_TYPE_UINT32);
 	if (!value) {
-		g_warning ("Missing or invalid required value " NMD_DEVICE_PROPS_STATE "!");
+		*out_error_message = "Missing or invalid required value " NMD_DEVICE_PROPS_STATE "!";
 		return NULL;
 	}
 	dev_state = g_variant_get_uint32 (value);
@@ -408,25 +413,25 @@ nm_dispatcher_utils_construct_envp (const char *action,
 
 	/* device itself */
 	if (!g_variant_lookup (device_props, NMD_DEVICE_PROPS_PATH, "o", NULL)) {
-		g_warning ("Missing or invalid required value " NMD_DEVICE_PROPS_PATH "!");
+		*out_error_message = "Missing or invalid required value " NMD_DEVICE_PROPS_PATH "!";
 		return NULL;
 	}
 
 	/* UUID and ID */
 	con_setting = g_variant_lookup_value (connection_dict, NM_SETTING_CONNECTION_SETTING_NAME, NM_VARIANT_TYPE_SETTING);
 	if (!con_setting) {
-		g_warning ("Failed to read connection setting");
+		*out_error_message = "Failed to read connection setting";
 		return NULL;
 	}
 
 	if (!g_variant_lookup (con_setting, NM_SETTING_CONNECTION_UUID, "&s", &uuid)) {
-		g_warning ("Connection hash did not contain the UUID");
+		*out_error_message = "Connection hash did not contain the UUID";
 		g_variant_unref (con_setting);
 		return NULL;
 	}
 
 	if (!g_variant_lookup (con_setting, NM_SETTING_CONNECTION_ID, "&s", &id)) {
-		g_warning ("Connection hash did not contain the ID");
+		*out_error_message = "Connection hash did not contain the ID";
 		g_variant_unref (con_setting);
 		return NULL;
 	}
@@ -473,6 +478,7 @@ nm_dispatcher_utils_construct_envp (const char *action,
 		envp[i] = (char *) iter->data;
 	g_slist_free (items);
 
+	*out_error_message = NULL;
 	return envp;
 }
 
diff --git a/callouts/nm-dispatcher-utils.h b/callouts/nm-dispatcher-utils.h
index f68b3ea6ae..40a0d41f1b 100644
--- a/callouts/nm-dispatcher-utils.h
+++ b/callouts/nm-dispatcher-utils.h
@@ -35,7 +35,8 @@ nm_dispatcher_utils_construct_envp (const char *action,
                                     const char *vpn_ip_iface,
                                     GVariant *vpn_ip4_props,
                                     GVariant *vpn_ip6_props,
-                                    char **out_iface);
+                                    char **out_iface,
+                                    const char **out_error_message);
 
 #endif  /* __NETWORKMANAGER_DISPATCHER_UTILS_H__ */
 
diff --git a/callouts/nm-dispatcher.c b/callouts/nm-dispatcher.c
index c769a8042d..6b665f4688 100644
--- a/callouts/nm-dispatcher.c
+++ b/callouts/nm-dispatcher.c
@@ -623,6 +623,7 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 	Request *request;
 	char **p;
 	guint i, num_nowait = 0;
+	const char *error_message = NULL;
 
 	sorted_scripts = find_scripts (str_action);
 
@@ -651,7 +652,11 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 	                                                    vpn_ip_iface,
 	                                                    vpn_ip4_props,
 	                                                    vpn_ip6_props,
-	                                                    &request->iface);
+	                                                    &request->iface,
+	                                                    &error_message);
+
+	if (error_message)
+		g_warning (error_message);
 
 	if (request->debug) {
 		g_message ("------------ Action ID %p '%s' Interface %s Environment ------------",
@@ -673,6 +678,15 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 	}
 	g_slist_free (sorted_scripts);
 
+	if (error_message) {
+		GVariant *results;
+
+		results = g_variant_new_array (G_VARIANT_TYPE ("(sus)"), NULL, 0);
+		g_dbus_method_invocation_return_value (context, g_variant_new ("(@a(sus))", results));
+		request_free (request);
+		return TRUE;
+	}
+
 	nm_clear_g_source (&quit_id);
 
 	h->num_requests_pending++;
diff --git a/callouts/tests/test-dispatcher-envp.c b/callouts/tests/test-dispatcher-envp.c
index faa6c085a0..420f507db5 100644
--- a/callouts/tests/test-dispatcher-envp.c
+++ b/callouts/tests/test-dispatcher-envp.c
@@ -458,6 +458,7 @@ test_generic (const char *file, const char *override_vpn_ip_iface)
 	char *expected_iface = NULL;
 	char *action = NULL;
 	char *out_iface = NULL;
+	const char *error_message = NULL;
 	GHashTable *expected_env = NULL;
 	GError *error = NULL;
 	gboolean success;
@@ -497,7 +498,13 @@ test_generic (const char *file, const char *override_vpn_ip_iface)
 	                                           override_vpn_ip_iface ? override_vpn_ip_iface : vpn_ip_iface,
 	                                           vpn_ip4_props,
 	                                           vpn_ip6_props,
-	                                           &out_iface);
+	                                           &out_iface,
+	                                           &error_message);
+
+	g_assert ((!denv && error_message) || (denv && !error_message));
+
+	if (error_message)
+		g_warning (error_message);
 
 	/* Print out environment for now */
 #ifdef DEBUG

From e7685f4304e1d05bebb653e044fa93c4aa136e06 Mon Sep 17 00:00:00 2001
From: Thomas Haller <thaller@redhat.com>
Date: Mon, 3 Aug 2015 15:52:11 +0200
Subject: [PATCH 8/8] dispatcher: refactor logging of nm-dispatcher

Refactor logging so that all logging lines for a request/script
have the same prefix, indicating the event to which they belong.

Previously, we only scheduled one script at a time so it was always
clear for which request a script belongs. Now we schedule scripts
in parallel, so we must know the event (request) for which we log
a message.
---
 callouts/nm-dispatcher.c | 121 +++++++++++++++++++++++++--------------
 1 file changed, 79 insertions(+), 42 deletions(-)

diff --git a/callouts/nm-dispatcher.c b/callouts/nm-dispatcher.c
index 6b665f4688..48399e62f6 100644
--- a/callouts/nm-dispatcher.c
+++ b/callouts/nm-dispatcher.c
@@ -46,6 +46,7 @@ static GMainLoop *loop = NULL;
 static gboolean debug = FALSE;
 static gboolean persist = FALSE;
 static guint quit_id;
+static guint request_id_counter = 0;
 
 typedef struct Request Request;
 
@@ -121,6 +122,8 @@ typedef struct {
 struct Request {
 	Handler *handler;
 
+	guint request_id;
+
 	GDBusMethodInvocation *context;
 	char *action;
 	char *iface;
@@ -133,6 +136,57 @@ struct Request {
 	gint num_scripts_nowait;
 };
 
+/*****************************************************************************/
+
+#define __LOG_print(print_cmd, _request, _script, ...) \
+	G_STMT_START { \
+		nm_assert ((_request) && (!(_script) || (_script)->request == (_request))); \
+		print_cmd ("#%u '%s'%s%s%s%s%s%s: " _NM_UTILS_MACRO_FIRST (__VA_ARGS__), \
+		           (_request)->request_id, \
+		           (_request)->action, \
+		           (_request)->iface ? " [" : "", \
+		           (_request)->iface ? (_request)->iface : "", \
+		           (_request)->iface ? "]" : "", \
+		           (_script) ? ", \"" : "", \
+		           (_script) ? (_script)->script : "", \
+		           (_script) ? "\"" : "" \
+		           _NM_UTILS_MACRO_REST (__VA_ARGS__)); \
+	} G_STMT_END
+
+#define _LOG(_request, _script, log_always, print_cmd, ...) \
+	G_STMT_START { \
+		const Request *__request = (_request); \
+		const ScriptInfo *__script = (_script); \
+		\
+		if (!__request) \
+			__request = __script->request; \
+		nm_assert (__request && (!__script || __script->request == __request)); \
+		if ((log_always) || __request->debug) { \
+			if (FALSE) { \
+				/* g_message() alone does not warn about invalid format. Add a dummy printf() statement to
+				 * get a compiler warning about wrong format. */ \
+				__LOG_print (printf, __request, __script, __VA_ARGS__); \
+			} \
+			__LOG_print (print_cmd, __request, __script, __VA_ARGS__); \
+		} \
+	} G_STMT_END
+
+static gboolean
+_LOG_R_D_enabled (const Request *request)
+{
+	return request->debug;
+}
+
+#define _LOG_R_D(_request, ...) _LOG(_request, NULL, FALSE, g_message, __VA_ARGS__)
+#define _LOG_R_I(_request, ...) _LOG(_request, NULL, TRUE,  g_message, __VA_ARGS__)
+#define _LOG_R_W(_request, ...) _LOG(_request, NULL, TRUE,  g_warning, __VA_ARGS__)
+
+#define _LOG_S_D(_script, ...)  _LOG(NULL, _script,  FALSE, g_message, __VA_ARGS__)
+#define _LOG_S_I(_script, ...)  _LOG(NULL, _script,  TRUE,  g_message, __VA_ARGS__)
+#define _LOG_S_W(_script, ...)  _LOG(NULL, _script,  TRUE,  g_warning, __VA_ARGS__)
+
+/*****************************************************************************/
+
 static void
 script_info_free (gpointer ptr)
 {
@@ -208,10 +262,7 @@ next_request (Handler *h, Request *request)
 			return FALSE;
 	}
 
-	if (request->iface)
-		g_message ("Dispatching action '%s' for %s", request->action, request->iface);
-	else
-		g_message ("Dispatching action '%s'", request->action);
+	_LOG_R_I (request, "start running ordered scripts...");
 
 	h->current_request = request;
 
@@ -254,12 +305,7 @@ complete_request (Request *request)
 	ret = g_variant_new ("(a(sus))", &results);
 	g_dbus_method_invocation_return_value (request->context, ret);
 
-	if (request->debug) {
-		if (request->iface)
-			g_message ("Dispatch '%s' on %s complete", request->action, request->iface);
-		else
-			g_message ("Dispatch '%s' complete", request->action);
-	}
+	_LOG_R_D (request, "completed (%u scripts)", request->scripts->len);
 
 	if (handler->current_request == request)
 		handler->current_request = NULL;
@@ -363,11 +409,10 @@ script_watch_cb (GPid pid, gint status, gpointer user_data)
 	}
 
 	if (script->result == DISPATCH_RESULT_SUCCESS) {
-		if (script->request->debug)
-			g_message ("Script '%s' complete", script->script);
+		_LOG_S_D (script, "complete");
 	} else {
 		script->result = DISPATCH_RESULT_FAILED;
-		g_warning ("%s", script->error);
+		_LOG_S_W (script, "complete: failed with %s", script->error);
 	}
 
 	g_spawn_close_pid (script->pid);
@@ -386,7 +431,7 @@ script_timeout_cb (gpointer user_data)
 	if (!script->wait)
 		script->request->num_scripts_nowait--;
 
-	g_warning ("Script '%s' took too long; killing it.", script->script);
+	_LOG_S_W (script, "complete: timeout (kill script)");
 
 	kill (script->pid, SIGKILL);
 again:
@@ -481,8 +526,7 @@ script_dispatch (ScriptInfo *script)
 	argv[2] = request->action;
 	argv[3] = NULL;
 
-	if (request->debug)
-		g_message ("Running script '%s'", script->script);
+	_LOG_S_D (script, "run script%s", script->wait ? "" : " (no-wait)");
 
 	if (g_spawn_async ("/", argv, request->envp, G_SPAWN_DO_NOT_REAP_CHILD, NULL, NULL, &script->pid, &error)) {
 		script->watch_id = g_child_watch_add (script->pid, (GChildWatchFunc) script_watch_cb, script);
@@ -491,8 +535,8 @@ script_dispatch (ScriptInfo *script)
 			request->num_scripts_nowait++;
 		return TRUE;
 	} else {
-		g_warning ("Failed to execute script '%s': (%d) %s",
-		           script->script, error->code, error->message);
+		_LOG_S_W (script, "complete: failed to execute script: %s (%d)",
+		          error->message, error->code);
 		script->result = DISPATCH_RESULT_EXEC_FAILED;
 		script->error = g_strdup (error->message);
 		request->num_scripts_done++;
@@ -536,7 +580,7 @@ find_scripts (const char *str_action)
 		dirname = NMD_SCRIPT_DIR_DEFAULT;
 
 	if (!(dir = g_dir_open (dirname, 0, &error))) {
-		g_message ("Failed to open dispatcher directory '%s': (%d) %s",
+		g_message ("find-scripts: Failed to open dispatcher directory '%s': (%d) %s",
 		           dirname, error->code, error->message);
 		g_error_free (error);
 		return NULL;
@@ -555,11 +599,11 @@ find_scripts (const char *str_action)
 
 		err = stat (path, &st);
 		if (err)
-			g_warning ("Failed to stat '%s': %d", path, err);
+			g_warning ("find-scripts: Failed to stat '%s': %d", path, err);
 		else if (S_ISDIR (st.st_mode))
 			; /* silently skip. */
 		else if (!check_permissions (&st, &err_msg))
-			g_warning ("Cannot execute '%s': %s", path, err_msg);
+			g_warning ("find-scripts: Cannot execute '%s': %s", path, err_msg);
 		else {
 			/* success */
 			sorted = g_slist_insert_sorted (sorted, path, (GCompareFunc) g_strcmp0);
@@ -627,15 +671,8 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 
 	sorted_scripts = find_scripts (str_action);
 
-	if (!sorted_scripts) {
-		GVariant *results;
-
-		results = g_variant_new_array (G_VARIANT_TYPE ("(sus)"), NULL, 0);
-		g_dbus_method_invocation_return_value (context, g_variant_new ("(@a(sus))", results));
-		return TRUE;
-	}
-
 	request = g_slice_new0 (Request);
+	request->request_id = ++request_id_counter;
 	request->handler = h;
 	request->debug = request_debug || debug;
 	request->context = context;
@@ -655,17 +692,6 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 	                                                    &request->iface,
 	                                                    &error_message);
 
-	if (error_message)
-		g_warning (error_message);
-
-	if (request->debug) {
-		g_message ("------------ Action ID %p '%s' Interface %s Environment ------------",
-		           context, str_action, request->iface ? request->iface : "(none)");
-		for (p = request->envp; *p; p++)
-			g_message ("  %s", *p);
-		g_message ("\n");
-	}
-
 	request->scripts = g_ptr_array_new_full (5, script_info_free);
 	for (iter = sorted_scripts; iter; iter = g_slist_next (iter)) {
 		ScriptInfo *s;
@@ -678,9 +704,20 @@ handle_action (NMDBusDispatcher *dbus_dispatcher,
 	}
 	g_slist_free (sorted_scripts);
 
-	if (error_message) {
+	_LOG_R_I (request, "new request (%u scripts)", request->scripts->len);
+	if (_LOG_R_D_enabled (request)) {
+		for (p = request->envp; *p; p++)
+			_LOG_R_D (request, "environment: %s", *p);
+	}
+
+	if (error_message || request->scripts->len == 0) {
 		GVariant *results;
 
+		if (error_message)
+			_LOG_R_W (request, "completed: invalid request: %s", error_message);
+		else
+			_LOG_R_I (request, "completed: no scripts");
+
 		results = g_variant_new_array (G_VARIANT_TYPE ("(sus)"), NULL, 0);
 		g_dbus_method_invocation_return_value (context, g_variant_new ("(@a(sus))", results));
 		request_free (request);
@@ -848,7 +885,7 @@ main (int argc, char **argv)
 	g_option_context_add_main_entries (opt_ctx, entries, NULL);
 
 	if (!g_option_context_parse (opt_ctx, &argc, &argv, &error)) {
-		g_warning ("%s\n", error->message);
+		g_warning ("Error parsing command line arguments: %s", error->message);
 		g_error_free (error);
 		return 1;
 	}