dispatcher: add better debugging

Add LOGD_DISPATCH, and if it's set to DEBUG, tell nm-dispatcher to log
additional information about each script it runs.

callouts/nm-dispatcher-action.c

@@ -83,6 +83,7 @@ impl_dispatch (Handler *h,
                const char *vpn_ip_iface,
                GHashTable *vpn_ip4_props,
                GHashTable *vpn_ip6_props,
+               gboolean request_debug,
                DBusGMethodInvocation *context);
 
 #include "nm-dispatcher-glue.h"
@@ -116,6 +117,8 @@ struct Request {
 	char *action;
 	char *iface;
 	char **envp;
+	gboolean debug;
+
 	GPtrArray *scripts;  /* list of ScriptInfo */
 	guint idx;
 
@@ -170,6 +173,11 @@ quit_timeout_reschedule (Handler *h)
 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);
 }
@@ -234,6 +242,13 @@ next_script (gpointer user_data)
 
 	dbus_g_method_return (request->context, results);
 	g_ptr_array_unref (results);
+
+	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);
+	}
 	request_free (request);
 
 	next_request (h);
@@ -271,7 +286,10 @@ script_watch_cb (GPid pid, gint status, gpointer user_data)
 		                                 script->script);
 	}
 
-	if (script->result != DISPATCH_RESULT_SUCCESS) {
+	if (script->result == DISPATCH_RESULT_SUCCESS) {
+		if (script->request->debug)
+			g_message ("Script '%s' complete", script->script);
+	} else {
 		script->result = DISPATCH_RESULT_FAILED;
 		g_warning ("%s", script->error);
 	}
@@ -379,8 +397,8 @@ dispatch_one_script (Request *request)
 	argv[2] = request->action;
 	argv[3] = NULL;
 
-	if (debug)
+	if (request->debug)
-		g_message ("Script: %s %s %s", script->script, request->iface ? request->iface : "(none)", request->action);
+		g_message ("Running script '%s'", script->script);
 
 	if (g_spawn_async ("/", argv, request->envp, G_SPAWN_DO_NOT_REAP_CHILD, child_setup, request, &script->pid, &error)) {
 		request->script_watch_id = g_child_watch_add (script->pid, (GChildWatchFunc) script_watch_cb, script);
@@ -451,6 +469,7 @@ impl_dispatch (Handler *h,
                const char *vpn_ip_iface,
                GHashTable *vpn_ip4_props,
                GHashTable *vpn_ip6_props,
+               gboolean request_debug,
                DBusGMethodInvocation *context)
 {
 	GSList *sorted_scripts = NULL;
@@ -470,6 +489,7 @@ impl_dispatch (Handler *h,
 
 	request = g_malloc0 (sizeof (*request));
 	request->handler = h;
+	request->debug = request_debug || debug;
 	request->context = context;
 	request->action = g_strdup (str_action);
 
@@ -486,7 +506,7 @@ impl_dispatch (Handler *h,
 	                                                    vpn_ip6_props,
 	                                                    &iface);
 
-	if (debug) {
+	if (request->debug) {
 		g_message ("------------ Action ID %p '%s' Interface %s Environment ------------",
 		           context, str_action, iface ? iface : "(none)");
 		for (p = request->envp; *p; p++)

callouts/nm-dispatcher.xml

@@ -75,6 +75,12 @@
         </tp:docstring>
       </arg>
 
+      <arg name="debug" type="b" direction="in">
+        <tp:docstring>
+          Whether to log debug output.
+        </tp:docstring>
+      </arg>
+
       <arg name="results" type="a(sus)" direction="out">
         <tp:docstring>
           Results of dispatching operations.  Each element of the returned

src/logging/nm-logging.c

@@ -50,7 +50,7 @@ nm_log_handler (const gchar *log_domain,
 	 LOGD_CORE | LOGD_DEVICE | LOGD_OLPC_MESH | LOGD_WIMAX | \
 	 LOGD_INFINIBAND | LOGD_FIREWALL | LOGD_ADSL | LOGD_BOND | \
 	 LOGD_VLAN | LOGD_BRIDGE | LOGD_DBUS_PROPS | LOGD_TEAM | LOGD_CONCHECK | \
-	 LOGD_DCB)
+	 LOGD_DCB | LOGD_DISPATCH)
 
 #define LOGD_DEFAULT (LOGD_ALL & ~(LOGD_WIFI_SCAN | LOGD_DBUS_PROPS))
 
@@ -108,6 +108,7 @@ static const LogDesc domain_descs[] = {
 	{ LOGD_TEAM,      "TEAM" },
 	{ LOGD_CONCHECK,  "CONCHECK" },
 	{ LOGD_DCB,       "DCB" },
+	{ LOGD_DISPATCH,  "DISPATCH" },
 	{ 0, NULL }
 };
 

src/logging/nm-logging.h

@@ -62,6 +62,7 @@ enum {
 	LOGD_TEAM       = (1LL << 32),
 	LOGD_CONCHECK   = (1LL << 33),
 	LOGD_DCB        = (1LL << 34), /* Data Center Bridging */
+	LOGD_DISPATCH   = (1LL << 35),
 };
 
 #define LOGD_DHCP (LOGD_DHCP4 | LOGD_DHCP6)

src/nm-dispatcher.c

@@ -179,7 +179,7 @@ dispatcher_done_cb (DBusGProxy *proxy, DBusGProxyCall *call, gpointer user_data)
 			DispatchResult result;
 
 			if (item->n_values != 3) {
-				nm_log_dbg (LOGD_CORE, "Unexpected number of items in "
+				nm_log_dbg (LOGD_DISPATCH, "Unexpected number of items in "
 				            "dispatcher result (got %d, expectd 3)",
 				            item->n_values);
 				goto next;
@@ -188,7 +188,7 @@ dispatcher_done_cb (DBusGProxy *proxy, DBusGProxyCall *call, gpointer user_data)
 			/* Script */
 			tmp = g_value_array_get_nth (item, 0);
 			if (G_VALUE_TYPE (tmp) != G_TYPE_STRING) {
-				nm_log_dbg (LOGD_CORE, "Dispatcher result %d element 0 invalid type %s",
+				nm_log_dbg (LOGD_DISPATCH, "Dispatcher result %d element 0 invalid type %s",
 				            i, G_VALUE_TYPE_NAME (tmp));
 				goto next;
 			}
@@ -197,7 +197,7 @@ dispatcher_done_cb (DBusGProxy *proxy, DBusGProxyCall *call, gpointer user_data)
 			/* Result */
 			tmp = g_value_array_get_nth (item, 1);
 			if (G_VALUE_TYPE (tmp) != G_TYPE_UINT) {
-				nm_log_dbg (LOGD_CORE, "Dispatcher result %d element 1 invalid type %s",
+				nm_log_dbg (LOGD_DISPATCH, "Dispatcher result %d element 1 invalid type %s",
 				            i, G_VALUE_TYPE_NAME (tmp));
 				goto next;
 			}
@@ -206,14 +206,14 @@ dispatcher_done_cb (DBusGProxy *proxy, DBusGProxyCall *call, gpointer user_data)
 			/* Error */
 			tmp = g_value_array_get_nth (item, 2);
 			if (G_VALUE_TYPE (tmp) != G_TYPE_STRING) {
-				nm_log_dbg (LOGD_CORE, "Dispatcher result %d element 2 invalid type %s",
+				nm_log_dbg (LOGD_DISPATCH, "Dispatcher result %d element 2 invalid type %s",
 				            i, G_VALUE_TYPE_NAME (tmp));
 				goto next;
 			}
 			err = g_value_get_string (tmp);
 
 			if (result != DISPATCH_RESULT_SUCCESS) {
-				nm_log_warn (LOGD_CORE, "Dispatcher script \"%s\" failed with %s: %s",
+				nm_log_warn (LOGD_DISPATCH, "Dispatcher script \"%s\" failed with %s: %s",
 				             script, dispatch_result_to_string (result), err);
 			}
 
@@ -223,7 +223,7 @@ next:
 		g_ptr_array_free (results, TRUE);
 	} else {
 		g_assert (error);
-		nm_log_warn (LOGD_CORE, "Dispatcher failed: (%d) %s", error->code, error->message);
+		nm_log_warn (LOGD_DISPATCH, "Dispatcher failed: (%d) %s", error->code, error->message);
 	}
 
 	if (info->callback)
@@ -285,8 +285,16 @@ _dispatcher_call (DispatcherAction action,
 	DispatchInfo *info;
 
 	/* All actions except 'hostname' require a device */
-	if (action != DISPATCHER_ACTION_HOSTNAME)
+	if (action == DISPATCHER_ACTION_HOSTNAME) {
+		nm_log_dbg (LOGD_DISPATCH, "dispatching action '%s'",
+		            action_to_string (action));
+	} else {
 		g_return_val_if_fail (NM_IS_DEVICE (device), NULL);
+
+		nm_log_dbg (LOGD_DISPATCH, "(%s) dispatching action '%s'",
+		            nm_device_get_iface (device), action_to_string (action));
+	}
+
 	/* VPN actions require at least an IPv4 config (for now) */
 	if (action == DISPATCHER_ACTION_VPN_UP)
 		g_return_val_if_fail (vpn_ip4_config != NULL, NULL);
@@ -297,7 +305,7 @@ _dispatcher_call (DispatcherAction action,
 	                                   NM_DISPATCHER_DBUS_PATH,
 	                                   NM_DISPATCHER_DBUS_IFACE);
 	if (!proxy) {
-		nm_log_err (LOGD_CORE, "could not get dispatcher proxy!");
+		nm_log_err (LOGD_DISPATCH, "could not get dispatcher proxy!");
 		return NULL;
 	}
 
@@ -354,6 +362,7 @@ _dispatcher_call (DispatcherAction action,
 	                                      G_TYPE_STRING, vpn_iface ? vpn_iface : "",
 	                                      DBUS_TYPE_G_MAP_OF_VARIANT, vpn_ip4_props,
 	                                      DBUS_TYPE_G_MAP_OF_VARIANT, vpn_ip6_props,
+	                                      G_TYPE_BOOLEAN, nm_logging_enabled (LOGL_DEBUG, LOGD_DISPATCH),
 	                                      G_TYPE_INVALID);
 	g_hash_table_destroy (connection_hash);
 	g_hash_table_destroy (connection_props);