From 211426e099f6d15e06ed25ebfd59d6e151a687e9 Mon Sep 17 00:00:00 2001 From: Philip Withnall Date: Wed, 3 Aug 2016 23:43:32 +0100 Subject: [PATCH] polkitbackend: Enable structured logging output This bumps polkit's GLib dependency to 2.49.4, but enables new features such as message IDs for log messages, inclusion of various key parameters as separate fields, and (probably most importantly) coloured log output. A custom log writer function is used to preserve the original behaviour of outputting everything to the journal, and outputting debug messages to stdout unless --no-debug is specified. https://bugs.freedesktop.org/show_bug.cgi?id=97342 --- configure.ac | 6 +- src/polkitbackend/polkitbackendauthority.c | 122 ++++++--------------- src/polkitbackend/polkitbackendauthority.h | 2 + .../polkitbackendinteractiveauthority.c | 15 +++ src/polkitbackend/polkitbackendjsauthority.c | 58 ++++++++-- src/polkitbackend/polkitd.c | 79 +++++++++---- 6 files changed, 165 insertions(+), 117 deletions(-) diff --git a/configure.ac b/configure.ac index 97d4222..d91a79b 100644 --- a/configure.ac +++ b/configure.ac @@ -121,12 +121,12 @@ if test "x$GCC" = "xyes"; then changequote([,])dnl fi -PKG_CHECK_MODULES(GLIB, [gmodule-2.0 gio-unix-2.0 >= 2.30.0]) +PKG_CHECK_MODULES(GLIB, [gmodule-2.0 gio-unix-2.0 >= 2.49.4]) AC_SUBST(GLIB_CFLAGS) AC_SUBST(GLIB_LIBS) -AC_DEFINE([GLIB_VERSION_MIN_REQUIRED], [GLIB_VERSION_2_30], +AC_DEFINE([GLIB_VERSION_MIN_REQUIRED], [GLIB_VERSION_2_50], [Avoid warning spew about g_type_init() being deprecated]) -AC_DEFINE([GLIB_VERSION_MAX_ALLOWED], [G_ENCODE_VERSION(2,34)], +AC_DEFINE([GLIB_VERSION_MAX_ALLOWED], [G_ENCODE_VERSION(2,50)], [Notify us when we'll need to transition away from g_type_init()]) AC_ARG_WITH(mozjs, AS_HELP_STRING([--with-mozjs=@<:@mozjs185/mozjs-17.0|auto@:>@], diff --git a/src/polkitbackend/polkitbackendauthority.c b/src/polkitbackend/polkitbackendauthority.c index 64560e1..cd0c74f 100644 --- a/src/polkitbackend/polkitbackendauthority.c +++ b/src/polkitbackend/polkitbackendauthority.c @@ -1440,93 +1440,45 @@ polkit_backend_authority_get (void) /* ---------------------------------------------------------------------------------------------------- */ -typedef enum -{ - _COLOR_RESET, - _COLOR_BOLD_ON, - _COLOR_INVERSE_ON, - _COLOR_BOLD_OFF, - _COLOR_FG_BLACK, - _COLOR_FG_RED, - _COLOR_FG_GREEN, - _COLOR_FG_YELLOW, - _COLOR_FG_BLUE, - _COLOR_FG_MAGENTA, - _COLOR_FG_CYAN, - _COLOR_FG_WHITE, - _COLOR_BG_RED, - _COLOR_BG_GREEN, - _COLOR_BG_YELLOW, - _COLOR_BG_BLUE, - _COLOR_BG_MAGENTA, - _COLOR_BG_CYAN, - _COLOR_BG_WHITE -} _Color; - -static gboolean _color_stdin_is_tty = FALSE; -static gboolean _color_initialized = FALSE; - -static void -_color_init (void) -{ - if (_color_initialized) - return; - _color_initialized = TRUE; - _color_stdin_is_tty = (isatty (STDIN_FILENO) != 0 && isatty (STDOUT_FILENO) != 0); -} - +/* Return value must be 1 byte long (plus nul byte). + * Reference: http://man7.org/linux/man-pages/man3/syslog.3.html#DESCRIPTION + */ static const gchar * -_color_get (_Color color) +log_level_to_priority (GLogLevelFlags log_level) { - const gchar *str; - - _color_init (); - - if (!_color_stdin_is_tty) - return ""; - - str = NULL; - switch (color) - { - case _COLOR_RESET: str="\x1b[0m"; break; - case _COLOR_BOLD_ON: str="\x1b[1m"; break; - case _COLOR_INVERSE_ON: str="\x1b[7m"; break; - case _COLOR_BOLD_OFF: str="\x1b[22m"; break; - case _COLOR_FG_BLACK: str="\x1b[30m"; break; - case _COLOR_FG_RED: str="\x1b[31m"; break; - case _COLOR_FG_GREEN: str="\x1b[32m"; break; - case _COLOR_FG_YELLOW: str="\x1b[33m"; break; - case _COLOR_FG_BLUE: str="\x1b[34m"; break; - case _COLOR_FG_MAGENTA: str="\x1b[35m"; break; - case _COLOR_FG_CYAN: str="\x1b[36m"; break; - case _COLOR_FG_WHITE: str="\x1b[37m"; break; - case _COLOR_BG_RED: str="\x1b[41m"; break; - case _COLOR_BG_GREEN: str="\x1b[42m"; break; - case _COLOR_BG_YELLOW: str="\x1b[43m"; break; - case _COLOR_BG_BLUE: str="\x1b[44m"; break; - case _COLOR_BG_MAGENTA: str="\x1b[45m"; break; - case _COLOR_BG_CYAN: str="\x1b[46m"; break; - case _COLOR_BG_WHITE: str="\x1b[47m"; break; - default: - g_assert_not_reached (); - break; - } - return str; + if (log_level & G_LOG_LEVEL_ERROR) + return "3"; + else if (log_level & G_LOG_LEVEL_CRITICAL) + return "4"; + else if (log_level & G_LOG_LEVEL_WARNING) + return "4"; + else if (log_level & G_LOG_LEVEL_MESSAGE) + return "5"; + else if (log_level & G_LOG_LEVEL_INFO) + return "6"; + else if (log_level & G_LOG_LEVEL_DEBUG) + return "7"; + + /* Default to LOG_NOTICE for custom log levels. */ + return "5"; } -/* ---------------------------------------------------------------------------------------------------- */ - void polkit_backend_authority_log (PolkitBackendAuthority *authority, + GLogLevelFlags log_level, + const gchar *message_id, const gchar *format, ...) { - GTimeVal now; - time_t now_time; - struct tm *now_tm; - gchar time_buf[128]; - gchar *message; + gchar *message = NULL; va_list var_args; + GLogField fields[] = { + { "MESSAGE", NULL, -1 }, + { "GLIB_DOMAIN", "polkitd-1", -1 }, + { "PRIORITY", log_level_to_priority (log_level), -1 }, + { "MESSAGE_ID", message_id, -1 }, + }; + gsize n_fields = G_N_ELEMENTS (fields); g_return_if_fail (POLKIT_BACKEND_IS_AUTHORITY (authority)); @@ -1534,17 +1486,11 @@ polkit_backend_authority_log (PolkitBackendAuthority *authority, message = g_strdup_vprintf (format, var_args); va_end (var_args); - syslog (LOG_NOTICE, "%s", message); - - g_get_current_time (&now); - now_time = (time_t) now.tv_sec; - now_tm = localtime (&now_time); - strftime (time_buf, sizeof time_buf, "%H:%M:%S", now_tm); - g_print ("%s%s%s.%03d%s: %s\n", - _color_get (_COLOR_BOLD_ON), _color_get (_COLOR_FG_YELLOW), - time_buf, (gint) now.tv_usec / 1000, - _color_get (_COLOR_RESET), - message); + fields[0].value = message; + if (message_id == NULL) + n_fields--; + + g_log_structured_array (log_level, fields, n_fields); g_free (message); } diff --git a/src/polkitbackend/polkitbackendauthority.h b/src/polkitbackend/polkitbackendauthority.h index 88df82e..b8b99e9 100644 --- a/src/polkitbackend/polkitbackendauthority.h +++ b/src/polkitbackend/polkitbackendauthority.h @@ -212,6 +212,8 @@ const gchar *polkit_backend_authority_get_version (PolkitBackendAut PolkitAuthorityFeatures polkit_backend_authority_get_features (PolkitBackendAuthority *authority); void polkit_backend_authority_log (PolkitBackendAuthority *authority, + GLogLevelFlags log_level, + const gchar *message_id, const gchar *format, ...); diff --git a/src/polkitbackend/polkitbackendinteractiveauthority.c b/src/polkitbackend/polkitbackendinteractiveauthority.c index ccfd608..23152a4 100644 --- a/src/polkitbackend/polkitbackendinteractiveauthority.c +++ b/src/polkitbackend/polkitbackendinteractiveauthority.c @@ -594,6 +594,8 @@ log_result (PolkitBackendInteractiveAuthority *authority, caller_cmdline = g_strdup (""); polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "2ed2a13f6eba4bc6a465f4d77757f254", "%s action %s for %s [%s] owned by %s (check requested by %s [%s])", log_result_str, action_id, @@ -702,6 +704,8 @@ check_authorization_challenge_cb (AuthenticationAgent *agent, if (is_temp) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "2eea6e852e3341b3acf038f46be1de91", "Operator of %s successfully authenticated as %s to gain " "TEMPORARY authorization for action %s for %s [%s] (owned by %s)", scope_str, @@ -714,6 +718,8 @@ check_authorization_challenge_cb (AuthenticationAgent *agent, else { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "70ea0ab81134444db773d31dfc3bd4c2", "Operator of %s successfully authenticated as %s to gain " "ONE-SHOT authorization for action %s for %s [%s] (owned by %s)", scope_str, @@ -727,6 +733,8 @@ check_authorization_challenge_cb (AuthenticationAgent *agent, else { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "ff24798d7a6e4707ba7facee26d5440b", "Operator of %s FAILED to authenticate to gain " "authorization for action %s for %s [%s] (owned by %s)", scope_str, @@ -1966,6 +1974,7 @@ append_property (GString *dest, else { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, NULL, "Error substituting value for property $(%s) when preparing message `%s' for action-id %s", key, message, @@ -2608,6 +2617,8 @@ polkit_backend_interactive_authority_register_authentication_agent (PolkitBacken locale); polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "91815797affe45a0a0959e50db3aab23", "Registered Authentication Agent for %s " "(system bus name %s [%s], object path %s, locale %s)", subject_as_string, @@ -2763,6 +2774,8 @@ polkit_backend_interactive_authority_unregister_authentication_agent (PolkitBack agent->locale); polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "29547ff31a2142648accefe6d6e59798", "Unregistered Authentication Agent for %s " "(system bus name %s, object path %s, locale %s)", scope_str, @@ -2915,6 +2928,8 @@ polkit_backend_interactive_authority_system_bus_name_owner_changed (PolkitBacken agent->object_path); polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "1e11d87633b341d0bb1cf884e877656c", "Unregistered Authentication Agent for %s " "(system bus name %s, object path %s, locale %s) (disconnected from bus)", scope_str, diff --git a/src/polkitbackend/polkitbackendjsauthority.c b/src/polkitbackend/polkitbackendjsauthority.c index 2112868..25b8e77 100644 --- a/src/polkitbackend/polkitbackendjsauthority.c +++ b/src/polkitbackend/polkitbackendjsauthority.c @@ -210,11 +210,29 @@ static void report_error (JSContext *cx, JSErrorReport *report) { PolkitBackendJsAuthority *authority = POLKIT_BACKEND_JS_AUTHORITY (JS_GetContextPrivate (cx)); - polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), - "%s:%u: %s", - report->filename ? report->filename : "", - (unsigned int) report->lineno, - message); + gchar *formatted_message = NULL, *formatted_line = NULL; + GLogField fields[] = { + { "MESSAGE", NULL, -1 }, + { "GLIB_DOMAIN", "polkitd-1", -1 }, + { "PRIORITY", "3", -1 }, + { "MESSAGE_ID", "1a384599f178498687279ac27aa741ec", -1 }, + { "POLKIT_JS_FILENAME", report->filename ? report->filename : "", -1 }, + { "POLKIT_JS_LINE", NULL, -1 }, + }; + gsize n_fields = G_N_ELEMENTS (fields); + + formatted_message = g_strdup_printf ("%s:%u: %s", + report->filename ? report->filename : "", + (unsigned int) report->lineno, message); + formatted_line = g_strdup_printf ("%u", (unsigned int) report->lineno); + + fields[0].value = formatted_message; + fields[5].value = formatted_line; + + g_log_structured_array (G_LOG_LEVEL_ERROR, fields, n_fields); + + g_free (formatted_line); + g_free (formatted_message); } static void @@ -270,6 +288,8 @@ load_scripts (PolkitBackendJsAuthority *authority) GDir *dir = NULL; polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "e05e5ac10aaa4c0689f316326430db20", "Loading rules from directory %s", dir_name); @@ -279,6 +299,7 @@ load_scripts (PolkitBackendJsAuthority *authority) if (dir == NULL) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, NULL, "Error opening rules directory: %s (%s, %d)", error->message, g_quark_to_string (error->domain), error->code); g_clear_error (&error); @@ -319,6 +340,8 @@ load_scripts (PolkitBackendJsAuthority *authority) if (script == NULL) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, + "93a4e22bbb9f4cc2bcf9b45cc277f500", "Error compiling script %s", filename); continue; @@ -331,6 +354,8 @@ load_scripts (PolkitBackendJsAuthority *authority) &rval)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, + "f93c9b32a70a49acbc61ea6702b5c8ce", "Error executing script %s", filename); continue; @@ -342,7 +367,9 @@ load_scripts (PolkitBackendJsAuthority *authority) } polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), - "Finished loading, compiling and executing %d rules", + G_LOG_LEVEL_MESSAGE, + "c665acb089a94531b0387d3c075e2d10", + "Finished loading, compiling and executing %u rules", num_scripts); g_list_free_full (files, g_free); } @@ -363,11 +390,13 @@ reload_scripts (PolkitBackendJsAuthority *authority) &rval)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, NULL, "Error deleting old rules, not loading new ones"); goto out; } polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, NULL, "Collecting garbage unconditionally..."); #if JS_VERSION == 186 JS_GC (authority->priv->rt); @@ -411,6 +440,8 @@ on_dir_monitor_changed (GFileMonitor *monitor, event_type == G_FILE_MONITOR_EVENT_CHANGES_DONE_HINT)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "734c72d5c8d146d0bc2f508c3e17d585", "Reloading rules"); reload_scripts (authority); } @@ -978,7 +1009,10 @@ js_operation_callback (JSContext *cx) g_mutex_unlock (&authority->priv->rkt_timeout_pending_mutex); /* Log that we are terminating the script */ - polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), "Terminating runaway script"); + polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "9c272bf73498482489d68ca9b1a43930", + "Terminating runaway script"); /* Throw an exception - this way the JS code can ignore the runaway script handling */ JS_SetOperationCallback (authority->priv->cx, NULL); @@ -1106,6 +1140,7 @@ polkit_backend_js_authority_get_admin_auth_identities (PolkitBackendInteractiveA if (!action_and_details_to_jsval (authority, action_id, details, &argv[0], &error)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, NULL, "Error converting action and details to JS object: %s", error->message); g_clear_error (&error); @@ -1121,6 +1156,7 @@ polkit_backend_js_authority_get_admin_auth_identities (PolkitBackendInteractiveA &error)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, NULL, "Error converting subject to JS object: %s", error->message); g_clear_error (&error); @@ -1134,6 +1170,8 @@ polkit_backend_js_authority_get_admin_auth_identities (PolkitBackendInteractiveA &rval)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, + "b9d40c5fcaa9453790e84371e42206ba", "Error evaluating admin rules"); goto out; } @@ -1163,6 +1201,7 @@ polkit_backend_js_authority_get_admin_auth_identities (PolkitBackendInteractiveA if (identity == NULL) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, NULL, "Identity `%s' is not valid, ignoring", identity_str); } @@ -1215,6 +1254,7 @@ polkit_backend_js_authority_check_authorization_sync (PolkitBackendInteractiveAu if (!action_and_details_to_jsval (authority, action_id, details, &argv[0], &error)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, NULL, "Error converting action and details to JS object: %s", error->message); g_clear_error (&error); @@ -1230,6 +1270,7 @@ polkit_backend_js_authority_check_authorization_sync (PolkitBackendInteractiveAu &error)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, NULL, "Error converting subject to JS object: %s", error->message); g_clear_error (&error); @@ -1243,6 +1284,8 @@ polkit_backend_js_authority_check_authorization_sync (PolkitBackendInteractiveAu &rval)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, + "cde8e8cf27064e2cbb5e5ce57c8817e9", "Error evaluating authorization rules"); goto out; } @@ -1274,6 +1317,7 @@ polkit_backend_js_authority_check_authorization_sync (PolkitBackendInteractiveAu if (!polkit_implicit_authorization_from_string (ret_str, &ret)) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_ERROR, NULL, "Returned result `%s' is not valid", ret_str); goto out; diff --git a/src/polkitbackend/polkitd.c b/src/polkitbackend/polkitd.c index 8d54ed7..df1f390 100644 --- a/src/polkitbackend/polkitd.c +++ b/src/polkitbackend/polkitd.c @@ -75,6 +75,8 @@ on_name_lost (GDBusConnection *connection, gpointer user_data) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "200d076b38ef4417b7c5e8a4c803fc8f", "Lost the name org.freedesktop.PolicyKit1 - exiting"); g_main_loop_quit (loop); } @@ -85,6 +87,8 @@ on_name_acquired (GDBusConnection *connection, gpointer user_data) { polkit_backend_authority_log (POLKIT_BACKEND_AUTHORITY (authority), + G_LOG_LEVEL_MESSAGE, + "ef0bb64915c24758aea79e1d887de28b", "Acquired the name org.freedesktop.PolicyKit1 on the system bus"); } @@ -153,6 +157,59 @@ become_user (const gchar *user, return ret; } +static GLogWriterOutput +log_writer (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data) +{ + GLogWriterOutput retval; + + g_return_val_if_fail (fields != NULL, G_LOG_WRITER_UNHANDLED); + g_return_val_if_fail (n_fields > 0, G_LOG_WRITER_UNHANDLED); + + /* Disable debug message output unless enabled on the command line. */ + if ((log_level & ~(G_LOG_LEVEL_INFO | G_LOG_LEVEL_DEBUG)) == 0 && + opt_no_debug) + return G_LOG_WRITER_HANDLED; + +/* TODO: prepend timestamp to output: + + GTimeVal now; + time_t now_time; + struct tm *now_tm; + gchar time_buf[128]; + + + g_get_current_time (&now); + now_time = (time_t) now.tv_sec; + now_tm = localtime (&now_time); + strftime (time_buf, sizeof time_buf, "%H:%M:%S", now_tm); + g_print ("%s%s%s.%03d%s: %s\n", + _color_get (_COLOR_BOLD_ON), _color_get (_COLOR_FG_YELLOW), + time_buf, (gint) now.tv_usec / 1000, + _color_get (_COLOR_RESET), + message); + + g_free (message); + +*/ + + /* Output on stdout/stderr unless they’re redirected to the journal, or output + * is disabled. */ + if (!opt_no_debug && + !g_log_writer_is_journald (fileno (stderr))) + retval = g_log_writer_standard_streams (log_level, fields, n_fields, + user_data); + + /* Always write to the journal. */ + if (g_log_writer_journald (log_level, fields, n_fields, user_data) == + G_LOG_WRITER_HANDLED) + retval = G_LOG_WRITER_HANDLED; + + return retval; +} + int main (int argc, char **argv) @@ -175,6 +232,9 @@ main (int argc, g_type_init (); + /* Set up the log writer function. */ + g_log_set_writer_func (log_writer, NULL, NULL); + opt_context = g_option_context_new ("polkit system daemon"); g_option_context_add_main_entries (opt_context, opt_entries, NULL); error = NULL; @@ -185,25 +245,6 @@ main (int argc, goto out; } - /* If --no-debug is requested don't clutter stdout/stderr etc. - */ - if (opt_no_debug) - { - gint dev_null_fd; - dev_null_fd = open ("/dev/null", O_RDWR); - if (dev_null_fd >= 0) - { - dup2 (dev_null_fd, STDIN_FILENO); - dup2 (dev_null_fd, STDOUT_FILENO); - dup2 (dev_null_fd, STDERR_FILENO); - close (dev_null_fd); - } - else - { - g_warning ("Error opening /dev/null: %m"); - } - } - error = NULL; if (!become_user (POLKITD_USER, &error)) { -- 2.7.4