diff options
author | Thomas Haller <thaller@redhat.com> | 2015-08-03 15:52:11 +0200 |
---|---|---|
committer | Beniamino Galvani <bgalvani@redhat.com> | 2015-08-25 15:27:19 +0200 |
commit | e7685f4304e1d05bebb653e044fa93c4aa136e06 (patch) | |
tree | 36d283a4fe32d5d994f5238ca5ff4de13fb69423 /callouts | |
parent | e81ba7594956f116b41c5a602269a0659435c433 (diff) | |
download | NetworkManager-e7685f4304e1d05bebb653e044fa93c4aa136e06.tar.gz |
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.
Diffstat (limited to 'callouts')
-rw-r--r-- | callouts/nm-dispatcher.c | 121 |
1 files 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; } |