colin/NetworkManager
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

dispatcher: enhance debug logging

Browse Source 
Attach a request ID to every request, and print that out in the debug
messages so you can see which results match up with which dispatcher
requests.
This commit is contained in:
Dan Williams
2014-06-02 16:26:05 -05:00
parent 1383f4bc14
commit df601ad68c
1 changed files with 52 additions and 34 deletions
Download Patch File Download Diff File Expand all files Collapse all files

86
src/nm-dispatcher.c
View File

@@ -182,8 +182,19 @@ dispatch_result_to_string (DispatchResult result)
g_assert_not_reached (); g_assert_not_reached ();
} }
static gboolean
validate_element (guint request_id, GValue *val, GType expected_type, guint idx, guint eltnum)
{
if (G_VALUE_TYPE (val) != expected_type) {
nm_log_dbg (LOGD_DISPATCH, "(%u) result %d element %d invalid type %s",
request_id, idx, eltnum, G_VALUE_TYPE_NAME (val));
return FALSE;
}
return TRUE;
}
static void static void
dispatcher_results_process (GPtrArray *results) dispatcher_results_process (guint request_id, GPtrArray *results)
{ {
guint i; guint i;
@@ -196,44 +207,43 @@ dispatcher_results_process (GPtrArray *results)
DispatchResult result; DispatchResult result;
if (item->n_values != 3) { if (item->n_values != 3) {
nm_log_dbg (LOGD_DISPATCH, "Unexpected number of items in " nm_log_dbg (LOGD_DISPATCH, "(%u) unexpected number of items in "
"dispatcher result (got %d, expectd 3)", "dispatcher result (got %d, expected 3)",
item->n_values); request_id, item->n_values);
continue; continue;
} }
/* Script */ /* Script */
tmp = g_value_array_get_nth (item, 0); tmp = g_value_array_get_nth (item, 0);
if (G_VALUE_TYPE (tmp) != G_TYPE_STRING) { if (!validate_element (request_id, tmp, G_TYPE_STRING, i, 0))
nm_log_dbg (LOGD_DISPATCH, "Dispatcher result %d element 0 invalid type %s",
i, G_VALUE_TYPE_NAME (tmp));
continue; continue;
}
script = g_value_get_string (tmp); script = g_value_get_string (tmp);
if (!script || strncmp (script, NMD_SCRIPT_DIR "/", STRLEN (NMD_SCRIPT_DIR "/")))
continue;
/* Result */ /* Result */
tmp = g_value_array_get_nth (item, 1); tmp = g_value_array_get_nth (item, 1);
if (G_VALUE_TYPE (tmp) != G_TYPE_UINT) { if (!validate_element (request_id, tmp, G_TYPE_UINT, i, 1))
nm_log_dbg (LOGD_DISPATCH, "Dispatcher result %d element 1 invalid type %s",
i, G_VALUE_TYPE_NAME (tmp));
continue; continue;
}
result = g_value_get_uint (tmp); result = g_value_get_uint (tmp);
/* Error */ /* Error */
tmp = g_value_array_get_nth (item, 2); tmp = g_value_array_get_nth (item, 2);
if (G_VALUE_TYPE (tmp) != G_TYPE_STRING) { if (!validate_element (request_id, tmp, G_TYPE_STRING, i, 2))
nm_log_dbg (LOGD_DISPATCH, "Dispatcher result %d element 2 invalid type %s",
i, G_VALUE_TYPE_NAME (tmp));
continue; continue;
}
err = g_value_get_string (tmp); err = g_value_get_string (tmp);
if (result == DISPATCH_RESULT_SUCCESS)
nm_log_dbg (LOGD_DISPATCH, "Dispatcher script \"%s\" succeeded", script); if (result == DISPATCH_RESULT_SUCCESS) {
else { nm_log_dbg (LOGD_DISPATCH, "(%u) %s succeeded",
nm_log_warn (LOGD_DISPATCH, "Dispatcher script \"%s\" failed with %s: %s", request_id,
script, dispatch_result_to_string (result), err); script + STRLEN (NMD_SCRIPT_DIR "/"));
} else {
nm_log_warn (LOGD_DISPATCH, "(%u) %s failed (%s): %s",
request_id,
script + STRLEN (NMD_SCRIPT_DIR "/"),
dispatch_result_to_string (result),
err ? err : "");
} }
} }
} }
@@ -256,11 +266,12 @@ dispatcher_done_cb (DBusGProxy *proxy, DBusGProxyCall *call, gpointer user_data)
if (dbus_g_proxy_end_call (proxy, call, &error, if (dbus_g_proxy_end_call (proxy, call, &error,
DISPATCHER_TYPE_RESULT_ARRAY, &results, DISPATCHER_TYPE_RESULT_ARRAY, &results,
G_TYPE_INVALID)) { G_TYPE_INVALID)) {
dispatcher_results_process (results); dispatcher_results_process (info->request_id, results);
free_results (results); free_results (results);
} else { } else {
g_assert (error); g_assert (error);
nm_log_warn (LOGD_DISPATCH, "Dispatcher failed: (%d) %s", error->code, error->message); nm_log_warn (LOGD_DISPATCH, "(%u) failed: (%d) %s",
info->request_id, error->code, error->message);
} }
if (info->callback) if (info->callback)
@@ -329,7 +340,12 @@ _dispatcher_call (DispatcherAction action,
DispatchInfo *info = NULL; DispatchInfo *info = NULL;
gboolean success = FALSE; gboolean success = FALSE;
GError *error = NULL; GError *error = NULL;
static guint request_counter = 1; static guint request_counter = 0;
guint reqid = ++request_counter;
/* Wrapping protection */
if (G_UNLIKELY (!reqid))
reqid = ++request_counter;
g_assert (!blocking || (!callback && !user_data)); g_assert (!blocking || (!callback && !user_data));
@@ -337,13 +353,15 @@ _dispatcher_call (DispatcherAction action,
/* All actions except 'hostname' require a device */ /* 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'", nm_log_dbg (LOGD_DISPATCH, "(%u) dispatching action '%s'",
action_to_string (action)); reqid, action_to_string (action));
} else { } else {
g_return_val_if_fail (NM_IS_DEVICE (device), FALSE); g_return_val_if_fail (NM_IS_DEVICE (device), FALSE);
nm_log_dbg (LOGD_DISPATCH, "(%s) dispatching action '%s'", nm_log_dbg (LOGD_DISPATCH, "(%u) (%s) dispatching action '%s'",
nm_device_get_iface (device), action_to_string (action)); reqid,
vpn_iface ? vpn_iface : nm_device_get_iface (device),
action_to_string (action));
} }
/* VPN actions require at least an IPv4 config (for now) */ /* VPN actions require at least an IPv4 config (for now) */
@@ -353,12 +371,12 @@ _dispatcher_call (DispatcherAction action,
if (do_dispatch == FALSE) { if (do_dispatch == FALSE) {
if (blocking == FALSE && (out_call_id || callback)) { if (blocking == FALSE && (out_call_id || callback)) {
info = g_malloc0 (sizeof (*info)); info = g_malloc0 (sizeof (*info));
info->request_id = request_counter++; info->request_id = reqid;
info->callback = callback; info->callback = callback;
info->user_data = user_data; info->user_data = user_data;
info->idle_id = g_idle_add (dispatcher_idle_cb, info); info->idle_id = g_idle_add (dispatcher_idle_cb, info);
} }
nm_log_dbg (LOGD_DISPATCH, "ignoring request; no scripts in " NMD_SCRIPT_DIR); nm_log_dbg (LOGD_DISPATCH, "(%u) ignoring request; no scripts in " NMD_SCRIPT_DIR, reqid);
success = TRUE; success = TRUE;
goto done; goto done;
} }
@@ -369,7 +387,7 @@ _dispatcher_call (DispatcherAction action,
NM_DISPATCHER_DBUS_PATH, NM_DISPATCHER_DBUS_PATH,
NM_DISPATCHER_DBUS_IFACE); NM_DISPATCHER_DBUS_IFACE);
if (!proxy) { if (!proxy) {
nm_log_err (LOGD_DISPATCH, "could not get dispatcher proxy!"); nm_log_err (LOGD_DISPATCH, "(%u) could not get dispatcher proxy!", reqid);
return FALSE; return FALSE;
} }
@@ -428,15 +446,15 @@ _dispatcher_call (DispatcherAction action,
DISPATCHER_TYPE_RESULT_ARRAY, &results, DISPATCHER_TYPE_RESULT_ARRAY, &results,
G_TYPE_INVALID); G_TYPE_INVALID);
if (success) { if (success) {
dispatcher_results_process (results); dispatcher_results_process (reqid, results);
free_results (results); free_results (results);
} else { } else {
nm_log_warn (LOGD_DISPATCH, "Dispatcher failed: (%d) %s", error->code, error->message); nm_log_warn (LOGD_DISPATCH, "(%u) failed: (%d) %s", reqid, error->code, error->message);
g_error_free (error); g_error_free (error);
} }
} else { } else {
info = g_malloc0 (sizeof (*info)); info = g_malloc0 (sizeof (*info));
info->request_id = request_counter++; info->request_id = reqid;
info->callback = callback; info->callback = callback;
info->user_data = user_data; info->user_data = user_data;
dbus_g_proxy_begin_call_with_timeout (proxy, "Action", dbus_g_proxy_begin_call_with_timeout (proxy, "Action",