diff options
| author | Michael Biebl <biebl@debian.org> | 2019-03-26 23:25:23 +0100 |
|---|---|---|
| committer | Michael Biebl <biebl@debian.org> | 2019-03-26 23:25:23 +0100 |
| commit | 9a6dcbf895f9da01768e64b73cec88c16157d91e (patch) | |
| tree | a359958930d731e9f1b59344642e10754419fe84 /src/nm-logging.c | |
| parent | 964ae8cc391520440cf5aa13e2b9cc34850ea6c2 (diff) | |
New upstream version 1.16.0 upstream/1.16.0
Diffstat (limited to 'src/nm-logging.c')
| -rw-r--r-- | src/nm-logging.c | 634 |
1 files changed, 392 insertions, 242 deletions
diff --git a/src/nm-logging.c b/src/nm-logging.c index 9e7d3892..1ee94645 100644 --- a/src/nm-logging.c +++ b/src/nm-logging.c @@ -21,43 +21,69 @@ #include "nm-default.h" +#include "nm-logging.h" + #include <dlfcn.h> #include <syslog.h> #include <stdio.h> #include <stdlib.h> #include <unistd.h> -#include <errno.h> #include <sys/wait.h> #include <sys/stat.h> #include <strings.h> -#include <string.h> #if SYSTEMD_JOURNAL #define SD_JOURNAL_SUPPRESS_LOCATION #include <systemd/sd-journal.h> #endif +#include "nm-utils/nm-time-utils.h" #include "nm-errors.h" -#include "nm-core-utils.h" - -/* often we have some static string where we need to know the maximum length. - * _MAX_LEN() returns @max but adds a debugging assertion that @str is indeed - * shorter then @mac. */ -#define _MAX_LEN(max, str) \ - ({ \ - const char *const _str = (str); \ - \ - nm_assert (_str && strlen (str) < (max)); \ - (max); \ - }) -void (*_nm_logging_clear_platform_logging_cache) (void); +/*****************************************************************************/ -static void -nm_log_handler (const char *log_domain, - GLogLevelFlags level, - const char *message, - gpointer ignored); +/* Notes about thread-safety: + * + * NetworkManager generally is single-threaded and uses a (GLib) mainloop. + * However, nm-logging is in parts thread-safe. That means: + * + * - functions that configure logging (nm_logging_init(), nm_logging_setup()) and + * most other functions MUST be called only from the main-thread. These functions + * are expected to be called infrequently, so they may or may not use a mutex + * (but the overhead is negligible here). + * + * - functions that do the actual logging logging (nm_log(), nm_logging_enabled()) are + * thread-safe and may be used from multiple threads. + * - When called from the not-main-thread, @mt_require_locking must be set to %TRUE. + * In this case, a Mutex will be used for accessing the global state. + * - When called from the main-thread, they may optionally pass @mt_require_locking %FALSE. + * This avoids extra locking and is in particular interesting for nm_logging_enabled(), + * which is expected to be called frequently and from the main-thread. + * + * Note that the logging macros honor %NM_THREAD_SAFE_ON_MAIN_THREAD define, to automatically + * set @mt_require_locking. That means, by default %NM_THREAD_SAFE_ON_MAIN_THREAD is "1", + * and code that only runs on the main-thread (which is the majority), can get away + * without locking. + */ + +/*****************************************************************************/ + +/* We have more then 32 logging domains. Assert that it compiles to a 64 bit sized enum */ +G_STATIC_ASSERT (sizeof (NMLogDomain) >= sizeof (guint64)); + +/* Combined domains */ +#define LOGD_ALL_STRING "ALL" +#define LOGD_DEFAULT_STRING "DEFAULT" +#define LOGD_DHCP_STRING "DHCP" +#define LOGD_IP_STRING "IP" + +/*****************************************************************************/ + +typedef enum { + LOG_BACKEND_GLIB, + LOG_BACKEND_SYSLOG, + LOG_BACKEND_JOURNAL, +} LogBackend; typedef struct { NMLogDomain num; @@ -80,6 +106,52 @@ typedef struct { GLogLevelFlags g_log_level; } LogLevelDesc; +typedef struct { + char *logging_domains_to_string; +} GlobalMain; + +typedef struct { + NMLogLevel log_level; + bool uses_syslog:1; + bool init_pre_done:1; + bool init_done:1; + bool debug_stderr:1; + const char *prefix; + const char *syslog_identifier; + + /* before we setup syslog (during start), the backend defaults to GLIB, meaning: + * we use g_log() for all logging. At that point, the application is not yet supposed + * to do any logging and doing so indicates a bug. + * + * Afterwards, the backend is either SYSLOG or JOURNAL. From that point, also + * g_log() is redirected to this backend via a logging handler. */ + LogBackend log_backend; +} Global; + +/*****************************************************************************/ + +G_LOCK_DEFINE_STATIC (log); + +/* This data must only be accessed from the main-thread (and as + * such does not need any lock). */ +static GlobalMain gl_main = { }; + +static union { + /* a union with an immutable and a mutable alias for the Global. + * Since nm-logging must be thread-safe, we must take care at which + * places we only read value ("imm") and where we modify them ("mut"). */ + Global mut; + const Global imm; +} gl = { + .imm = { + /* nm_logging_setup ("INFO", LOGD_DEFAULT_STRING, NULL, NULL); */ + .log_level = LOGL_INFO, + .log_backend = LOG_BACKEND_GLIB, + .syslog_identifier = "SYSLOG_IDENTIFIER="G_LOG_DOMAIN, + .prefix = "", + }, +}; + NMLogDomain _nm_logging_enabled_state[_LOGL_N_REAL] = { /* nm_logging_setup ("INFO", LOGD_DEFAULT_STRING, NULL, NULL); * @@ -90,102 +162,65 @@ NMLogDomain _nm_logging_enabled_state[_LOGL_N_REAL] = { [LOGL_ERR] = LOGD_DEFAULT, }; -static struct Global { - NMLogLevel log_level; - bool uses_syslog:1; - bool syslog_identifier_initialized:1; - bool debug_stderr:1; - const char *prefix; - const char *syslog_identifier; - enum { - /* before we setup syslog (during start), the backend defaults to GLIB, meaning: - * we use g_log() for all logging. At that point, the application is not yet supposed - * to do any logging and doing so indicates a bug. - * - * Afterwards, the backend is either SYSLOG or JOURNAL. From that point, also - * g_log() is redirected to this backend via a logging handler. */ - LOG_BACKEND_GLIB, - LOG_BACKEND_SYSLOG, - LOG_BACKEND_JOURNAL, - } log_backend; - char *logging_domains_to_string; - const LogLevelDesc level_desc[_LOGL_N]; - -#define _DOMAIN_DESC_LEN 39 - /* Would be nice to use C99 flexible array member here, - * but that feature doesn't seem well supported. */ - const LogDesc domain_desc[_DOMAIN_DESC_LEN]; -} global = { - /* nm_logging_setup ("INFO", LOGD_DEFAULT_STRING, NULL, NULL); */ - .log_level = LOGL_INFO, - .log_backend = LOG_BACKEND_GLIB, - .syslog_identifier = "SYSLOG_IDENTIFIER="G_LOG_DOMAIN, - .prefix = "", - .level_desc = { - [LOGL_TRACE] = { "TRACE", "<trace>", LOG_DEBUG, G_LOG_LEVEL_DEBUG, }, - [LOGL_DEBUG] = { "DEBUG", "<debug>", LOG_DEBUG, G_LOG_LEVEL_DEBUG, }, - [LOGL_INFO] = { "INFO", "<info>", LOG_INFO, G_LOG_LEVEL_INFO, }, - [LOGL_WARN] = { "WARN", "<warn>", LOG_WARNING, G_LOG_LEVEL_MESSAGE, }, - [LOGL_ERR] = { "ERR", "<error>", LOG_ERR, G_LOG_LEVEL_MESSAGE, }, - [_LOGL_OFF] = { "OFF", NULL, 0, 0, }, - [_LOGL_KEEP] = { "KEEP", NULL, 0, 0, }, - }, - .domain_desc = { - { LOGD_PLATFORM, "PLATFORM" }, - { LOGD_RFKILL, "RFKILL" }, - { LOGD_ETHER, "ETHER" }, - { LOGD_WIFI, "WIFI" }, - { LOGD_BT, "BT" }, - { LOGD_MB, "MB" }, - { LOGD_DHCP4, "DHCP4" }, - { LOGD_DHCP6, "DHCP6" }, - { LOGD_PPP, "PPP" }, - { LOGD_WIFI_SCAN, "WIFI_SCAN" }, - { LOGD_IP4, "IP4" }, - { LOGD_IP6, "IP6" }, - { LOGD_AUTOIP4, "AUTOIP4" }, - { LOGD_DNS, "DNS" }, - { LOGD_VPN, "VPN" }, - { LOGD_SHARING, "SHARING" }, - { LOGD_SUPPLICANT,"SUPPLICANT" }, - { LOGD_AGENTS, "AGENTS" }, - { LOGD_SETTINGS, "SETTINGS" }, - { LOGD_SUSPEND, "SUSPEND" }, - { LOGD_CORE, "CORE" }, - { LOGD_DEVICE, "DEVICE" }, - { LOGD_OLPC, "OLPC" }, - { LOGD_INFINIBAND,"INFINIBAND" }, - { LOGD_FIREWALL, "FIREWALL" }, - { LOGD_ADSL, "ADSL" }, - { LOGD_BOND, "BOND" }, - { LOGD_VLAN, "VLAN" }, - { LOGD_BRIDGE, "BRIDGE" }, - { LOGD_DBUS_PROPS,"DBUS_PROPS" }, - { LOGD_TEAM, "TEAM" }, - { LOGD_CONCHECK, "CONCHECK" }, - { LOGD_DCB, "DCB" }, - { LOGD_DISPATCH, "DISPATCH" }, - { LOGD_AUDIT, "AUDIT" }, - { LOGD_SYSTEMD, "SYSTEMD" }, - { LOGD_VPN_PLUGIN,"VPN_PLUGIN" }, - { LOGD_PROXY, "PROXY" }, - { 0, NULL } - /* keep _DOMAIN_DESC_LEN in sync */ - }, -}; +/*****************************************************************************/ -/* We have more then 32 logging domains. Assert that it compiles to a 64 bit sized enum */ -G_STATIC_ASSERT (sizeof (NMLogDomain) >= sizeof (guint64)); +static const LogLevelDesc level_desc[_LOGL_N] = { + [LOGL_TRACE] = { "TRACE", "<trace>", LOG_DEBUG, G_LOG_LEVEL_DEBUG, }, + [LOGL_DEBUG] = { "DEBUG", "<debug>", LOG_DEBUG, G_LOG_LEVEL_DEBUG, }, + [LOGL_INFO] = { "INFO", "<info>", LOG_INFO, G_LOG_LEVEL_INFO, }, + [LOGL_WARN] = { "WARN", "<warn>", LOG_WARNING, G_LOG_LEVEL_MESSAGE, }, + [LOGL_ERR] = { "ERR", "<error>", LOG_ERR, G_LOG_LEVEL_MESSAGE, }, + [_LOGL_OFF] = { "OFF", NULL, 0, 0, }, + [_LOGL_KEEP] = { "KEEP", NULL, 0, 0, }, +}; -/* Combined domains */ -#define LOGD_ALL_STRING "ALL" -#define LOGD_DEFAULT_STRING "DEFAULT" -#define LOGD_DHCP_STRING "DHCP" -#define LOGD_IP_STRING "IP" +static const LogDesc domain_desc[] = { + { LOGD_PLATFORM, "PLATFORM" }, + { LOGD_RFKILL, "RFKILL" }, + { LOGD_ETHER, "ETHER" }, + { LOGD_WIFI, "WIFI" }, + { LOGD_BT, "BT" }, + { LOGD_MB, "MB" }, + { LOGD_DHCP4, "DHCP4" }, + { LOGD_DHCP6, "DHCP6" }, + { LOGD_PPP, "PPP" }, + { LOGD_WIFI_SCAN, "WIFI_SCAN" }, + { LOGD_IP4, "IP4" }, + { LOGD_IP6, "IP6" }, + { LOGD_AUTOIP4, "AUTOIP4" }, + { LOGD_DNS, "DNS" }, + { LOGD_VPN, "VPN" }, + { LOGD_SHARING, "SHARING" }, + { LOGD_SUPPLICANT,"SUPPLICANT" }, + { LOGD_AGENTS, "AGENTS" }, + { LOGD_SETTINGS, "SETTINGS" }, + { LOGD_SUSPEND, "SUSPEND" }, + { LOGD_CORE, "CORE" }, + { LOGD_DEVICE, "DEVICE" }, + { LOGD_OLPC, "OLPC" }, + { LOGD_INFINIBAND,"INFINIBAND" }, + { LOGD_FIREWALL, "FIREWALL" }, + { LOGD_ADSL, "ADSL" }, + { LOGD_BOND, "BOND" }, + { LOGD_VLAN, "VLAN" }, + { LOGD_BRIDGE, "BRIDGE" }, + { LOGD_DBUS_PROPS,"DBUS_PROPS" }, + { LOGD_TEAM, "TEAM" }, + { LOGD_CONCHECK, "CONCHECK" }, + { LOGD_DCB, "DCB" }, + { LOGD_DISPATCH, "DISPATCH" }, + { LOGD_AUDIT, "AUDIT" }, + { LOGD_SYSTEMD, "SYSTEMD" }, + { LOGD_VPN_PLUGIN,"VPN_PLUGIN" }, + { LOGD_PROXY, "PROXY" }, + { 0 }, +}; /*****************************************************************************/ -static char *_domains_to_string (gboolean include_level_override); +static char *_domains_to_string (gboolean include_level_override, + NMLogLevel log_level, + const NMLogDomain log_state[static _LOGL_N_REAL]); /*****************************************************************************/ @@ -211,48 +246,30 @@ _syslog_identifier_valid_domain (const char *domain) } static gboolean -_syslog_identifier_assert (const struct Global *gl) +_syslog_identifier_assert (const char *syslog_identifier) { - g_assert (gl); - g_assert (gl->syslog_identifier); - g_assert (g_str_has_prefix (gl->syslog_identifier, "SYSLOG_IDENTIFIER=")); - g_assert (_syslog_identifier_valid_domain (&gl->syslog_identifier[NM_STRLEN ("SYSLOG_IDENTIFIER=")])); + g_assert (syslog_identifier); + g_assert (g_str_has_prefix (syslog_identifier, "SYSLOG_IDENTIFIER=")); + g_assert (_syslog_identifier_valid_domain (&syslog_identifier[NM_STRLEN ("SYSLOG_IDENTIFIER=")])); return TRUE; } static const char * -syslog_identifier_domain (const struct Global *gl) +syslog_identifier_domain (const char *syslog_identifier) { - nm_assert (_syslog_identifier_assert (gl)); - return &gl->syslog_identifier[NM_STRLEN ("SYSLOG_IDENTIFIER=")]; + nm_assert (_syslog_identifier_assert (syslog_identifier)); + return &syslog_identifier[NM_STRLEN ("SYSLOG_IDENTIFIER=")]; } #if SYSTEMD_JOURNAL static const char * -syslog_identifier_full (const struct Global *gl) +syslog_identifier_full (const char *syslog_identifier) { - nm_assert (_syslog_identifier_assert (gl)); - return &gl->syslog_identifier[0]; + nm_assert (_syslog_identifier_assert (syslog_identifier)); + return &syslog_identifier[0]; } #endif -void -nm_logging_set_syslog_identifier (const char *domain) -{ - if (global.log_backend != LOG_BACKEND_GLIB) - g_return_if_reached (); - - if (!_syslog_identifier_valid_domain (domain)) - g_return_if_reached (); - - if (global.syslog_identifier_initialized) - g_return_if_reached (); - - global.syslog_identifier_initialized = TRUE; - global.syslog_identifier = g_strdup_printf ("SYSLOG_IDENTIFIER=%s", domain); - nm_assert (_syslog_identifier_assert (&global)); -} - /*****************************************************************************/ static gboolean @@ -262,8 +279,8 @@ match_log_level (const char *level, { int i; - for (i = 0; i < G_N_ELEMENTS (global.level_desc); i++) { - if (!g_ascii_strcasecmp (global.level_desc[i].name, level)) { + for (i = 0; i < G_N_ELEMENTS (level_desc); i++) { + if (!g_ascii_strcasecmp (level_desc[i].name, level)) { *out_level = i; return TRUE; } @@ -281,31 +298,42 @@ nm_logging_setup (const char *level, GError **error) { GString *unrecognized = NULL; - NMLogDomain new_logging[G_N_ELEMENTS (_nm_logging_enabled_state)]; - NMLogLevel new_log_level = global.log_level; + NMLogDomain cur_log_state[_LOGL_N_REAL]; + NMLogDomain new_log_state[_LOGL_N_REAL]; + NMLogLevel cur_log_level; + NMLogLevel new_log_level; char **tmp, **iter; int i; gboolean had_platform_debug; gs_free char *domains_free = NULL; + NM_ASSERT_ON_MAIN_THREAD (); + g_return_val_if_fail (!bad_domains || !*bad_domains, FALSE); g_return_val_if_fail (!error || !*error, FALSE); - /* domains */ - if (!domains || !*domains) - domains = (domains_free = _domains_to_string (FALSE)); + cur_log_level = gl.imm.log_level; + memcpy (cur_log_state, _nm_logging_enabled_state, sizeof (cur_log_state)); + + new_log_level = cur_log_level; + + if (!domains || !*domains) { + domains_free = _domains_to_string (FALSE, + cur_log_level, + cur_log_state); + domains = domains_free; + } - for (i = 0; i < G_N_ELEMENTS (new_logging); i++) - new_logging[i] = 0; + for (i = 0; i < G_N_ELEMENTS (new_log_state); i++) + new_log_state[i] = 0; - /* levels */ if (level && *level) { if (!match_log_level (level, &new_log_level, error)) return FALSE; if (new_log_level == _LOGL_KEEP) { - new_log_level = global.log_level; - for (i = 0; i < G_N_ELEMENTS (new_logging); i++) - new_logging[i] = _nm_logging_enabled_state[i]; + new_log_level = cur_log_level; + for (i = 0; i < G_N_ELEMENTS (new_log_state); i++) + new_log_state[i] = cur_log_state[i]; } } @@ -362,7 +390,7 @@ nm_logging_setup (const char *level, continue; else { - for (diter = &global.domain_desc[0]; diter->name; diter++) { + for (diter = &domain_desc[0]; diter->name; diter++) { if (!g_ascii_strcasecmp (diter->name, *iter)) { bits = diter->num; break; @@ -386,34 +414,37 @@ nm_logging_setup (const char *level, } if (domain_log_level == _LOGL_KEEP) { - for (i = 0; i < G_N_ELEMENTS (new_logging); i++) - new_logging[i] = (new_logging[i] & ~bits) | (_nm_logging_enabled_state[i] & bits); + for (i = 0; i < G_N_ELEMENTS (new_log_state); i++) + new_log_state[i] = (new_log_state[i] & ~bits) | (cur_log_state[i] & bits); } else { - for (i = 0; i < G_N_ELEMENTS (new_logging); i++) { + for (i = 0; i < G_N_ELEMENTS (new_log_state); i++) { if (i < domain_log_level) - new_logging[i] &= ~bits; + new_log_state[i] &= ~bits; else { - new_logging[i] |= bits; + new_log_state[i] |= bits; if ( (protect & bits) && i < LOGL_INFO) - new_logging[i] &= ~protect; + new_log_state[i] &= ~protect; } } } } g_strfreev (tmp); - g_clear_pointer (&global.logging_domains_to_string, g_free); + g_clear_pointer (&gl_main.logging_domains_to_string, g_free); - had_platform_debug = nm_logging_enabled (LOGL_DEBUG, LOGD_PLATFORM); + had_platform_debug = _nm_logging_enabled_lockfree (LOGL_DEBUG, LOGD_PLATFORM); - global.log_level = new_log_level; - for (i = 0; i < G_N_ELEMENTS (new_logging); i++) - _nm_logging_enabled_state[i] = new_logging[i]; + G_LOCK (log); + + gl.mut.log_level = new_log_level; + for (i = 0; i < G_N_ELEMENTS (new_log_state); i++) + _nm_logging_enabled_state[i] = new_log_state[i]; + + G_UNLOCK (log); if ( had_platform_debug - && _nm_logging_clear_platform_logging_cache - && !nm_logging_enabled (LOGL_DEBUG, LOGD_PLATFORM)) { + && !_nm_logging_enabled_lockfree (LOGL_DEBUG, LOGD_PLATFORM)) { /* when debug logging is enabled, platform will cache all access to * sysctl. When the user disables debug-logging, we want to clear that * cache right away. */ @@ -429,7 +460,9 @@ nm_logging_setup (const char *level, const char * nm_logging_level_to_string (void) { - return global.level_desc[global.log_level].name; + NM_ASSERT_ON_MAIN_THREAD (); + + return level_desc[gl.imm.log_level].name; } const char * @@ -441,10 +474,10 @@ nm_logging_all_levels_to_string (void) int i; str = g_string_new (NULL); - for (i = 0; i < G_N_ELEMENTS (global.level_desc); i++) { + for (i = 0; i < G_N_ELEMENTS (level_desc); i++) { if (str->len) g_string_append_c (str, ','); - g_string_append (str, global.level_desc[i].name); + g_string_append (str, level_desc[i].name); } } @@ -454,27 +487,34 @@ nm_logging_all_levels_to_string (void) const char * nm_logging_domains_to_string (void) { - if (G_UNLIKELY (!global.logging_domains_to_string)) - global.logging_domains_to_string = _domains_to_string (TRUE); + NM_ASSERT_ON_MAIN_THREAD (); + + if (G_UNLIKELY (!gl_main.logging_domains_to_string)) { + gl_main.logging_domains_to_string = _domains_to_string (TRUE, + gl.imm.log_level, + _nm_logging_enabled_state); + } - return global.logging_domains_to_string; + return gl_main.logging_domains_to_string; } static char * -_domains_to_string (gboolean include_level_override) +_domains_to_string (gboolean include_level_override, + NMLogLevel log_level, + const NMLogDomain log_state[static _LOGL_N_REAL]) { const LogDesc *diter; GString *str; int i; - /* We don't just return g_strdup (global.log_domains) because we want to expand - * "DEFAULT" and "ALL". + /* We don't just return g_strdup() the logging domains that were set during + * nm_logging_setup(), because we want to expand "DEFAULT" and "ALL". */ str = g_string_sized_new (75); - for (diter = &global.domain_desc[0]; diter->name; diter++) { + for (diter = &domain_desc[0]; diter->name; diter++) { /* If it's set for any lower level, it will also be set for LOGL_ERR */ - if (!(diter->num & _nm_logging_enabled_state[LOGL_ERR])) + if (!(diter->num & log_state[LOGL_ERR])) continue; if (str->len) @@ -485,17 +525,17 @@ _domains_to_string (gboolean include_level_override) continue; /* Check if it's logging at a lower level than the default. */ - for (i = 0; i < global.log_level; i++) { - if (diter->num & _nm_logging_enabled_state[i]) { - g_string_append_printf (str, ":%s", global.level_desc[i].name); + for (i = 0; i < log_level; i++) { + if (diter->num & log_state[i]) { + g_string_append_printf (str, ":%s", level_desc[i].name); break; } } /* Check if it's logging at a higher level than the default. */ - if (!(diter->num & _nm_logging_enabled_state[global.log_level])) { - for (i = global.log_level + 1; i < G_N_ELEMENTS (_nm_logging_enabled_state); i++) { - if (diter->num & _nm_logging_enabled_state[i]) { - g_string_append_printf (str, ":%s", global.level_desc[i].name); + if (!(diter->num & log_state[log_level])) { + for (i = log_level + 1; i < _LOGL_N_REAL; i++) { + if (diter->num & log_state[i]) { + g_string_append_printf (str, ":%s", level_desc[i].name); break; } } @@ -513,7 +553,7 @@ nm_logging_all_domains_to_string (void) const LogDesc *diter; str = g_string_new (LOGD_DEFAULT_STRING); - for (diter = &global.domain_desc[0]; diter->name; diter++) { + for (diter = &domain_desc[0]; diter->name; diter++) { g_string_append_c (str, ','); g_string_append (str, diter->name); if (diter->num == LOGD_DHCP6) @@ -543,11 +583,31 @@ nm_logging_get_level (NMLogDomain domain) G_STATIC_ASSERT (LOGL_TRACE == 0); while ( sl > LOGL_TRACE - && nm_logging_enabled (sl - 1, domain)) + && _nm_logging_enabled_lockfree (sl - 1, domain)) sl--; return sl; } +gboolean +_nm_logging_enabled_locking (NMLogLevel level, + NMLogDomain domain) +{ + gboolean v; + + G_LOCK (log); + v = _nm_logging_enabled_lockfree (level, domain); + G_UNLOCK (log); + return v; +} + +gboolean +_nm_log_enabled_impl (gboolean mt_require_locking, + NMLogLevel level, + NMLogDomain domain) +{ + return nm_logging_enabled_mt (mt_require_locking, level, domain); +} + #if SYSTEMD_JOURNAL static void _iovec_set (struct iovec *iov, const void *str, gsize len) @@ -583,20 +643,32 @@ _iovec_set_format (struct iovec *iov, gpointer *iov_free, const char *format, .. char *const _buf = g_alloca (_size); \ int _len; \ \ + G_STATIC_ASSERT_EXPR ((reserve_extra) + (NM_STRLEN (format) + 3) <= 96); \ + \ _len = g_snprintf (_buf, _size, ""format"", ##__VA_ARGS__);\ \ nm_assert (_len >= 0); \ - nm_assert (_len <= _size); \ + nm_assert (_len < _size); \ nm_assert (_len == strlen (_buf)); \ \ _iovec_set ((iov), _buf, _len); \ } G_STMT_END + +#define _iovec_set_format_str_a(iov, max_str_len, format, str_arg) \ + G_STMT_START { \ + const char *_str_arg = (str_arg); \ + \ + nm_assert (_str_arg && strlen (_str_arg) < (max_str_len)); \ + _iovec_set_format_a ((iov), (max_str_len), format, str_arg); \ + } G_STMT_END + #endif void _nm_log_impl (const char *file, guint line, const char *func, + gboolean mt_require_locking, NMLogLevel level, NMLogDomain domain, int error, @@ -608,15 +680,37 @@ _nm_log_impl (const char *file, va_list args; char *msg; GTimeVal tv; - int errno_saved; - - if ((guint) level >= G_N_ELEMENTS (_nm_logging_enabled_state)) - g_return_if_reached (); + int errsv; + const NMLogDomain *cur_log_state; + NMLogDomain cur_log_state_copy[_LOGL_N_REAL]; + Global g_copy; + const Global *g; + + if (G_UNLIKELY (mt_require_locking)) { + G_LOCK (log); + /* we evaluate logging-enabled under lock. There is still a race that + * we might log the message below *after* logging was disabled. That means, + * when disabling logging, we might still log messages. */ + if (!_nm_logging_enabled_lockfree (level, domain)) { + G_UNLOCK (log); + return; + } + g_copy = gl.imm; + memcpy (cur_log_state_copy, _nm_logging_enabled_state, sizeof (cur_log_state_copy)); + G_UNLOCK (log); + g = &g_copy; + cur_log_state = cur_log_state_copy; + } else { + NM_ASSERT_ON_MAIN_THREAD (); + if (!_nm_logging_enabled_lockfree (level, domain)) + return; + g = &gl.imm; + cur_log_state = _nm_logging_enabled_state; + } - if (!(_nm_logging_enabled_state[level] & domain)) - return; + (void) cur_log_state; - errno_saved = errno; + errsv = errno; /* Make sure that %m maps to the specified error */ if (error != 0) { @@ -630,19 +724,19 @@ _nm_log_impl (const char *file, va_end (args); #define MESSAGE_FMT "%s%-7s [%ld.%04ld] %s" -#define MESSAGE_ARG(global, tv, msg) \ - (global).prefix, \ - (global).level_desc[level].level_str, \ +#define MESSAGE_ARG(prefix, tv, msg) \ + prefix, \ + level_desc[level].level_str, \ (tv).tv_sec, \ ((tv).tv_usec / 100), \ (msg) g_get_current_time (&tv); - if (global.debug_stderr) - g_printerr (MESSAGE_FMT"\n", MESSAGE_ARG (global, tv, msg)); + if (g->debug_stderr) + g_printerr (MESSAGE_FMT"\n", MESSAGE_ARG (g->prefix, tv, msg)); - switch (global.log_backend) { + switch (g->log_backend) { #if SYSTEMD_JOURNAL case LOG_BACKEND_JOURNAL: { @@ -657,18 +751,18 @@ _nm_log_impl (const char *file, now = nm_utils_get_monotonic_timestamp_ns (); boottime = nm_utils_monotonic_timestamp_as_boottime (now, 1); - _iovec_set_format_a (iov++, 30, "PRIORITY=%d", global.level_desc[level].syslog_level); - _iovec_set_format (iov++, iov_free++, "MESSAGE="MESSAGE_FMT, MESSAGE_ARG (global, tv, msg)); - _iovec_set_string (iov++, syslog_identifier_full (&global)); + _iovec_set_format_a (iov++, 30, "PRIORITY=%d", level_desc[level].syslog_level); + _iovec_set_format (iov++, iov_free++, "MESSAGE="MESSAGE_FMT, MESSAGE_ARG (g->prefix, tv, msg)); + _iovec_set_string (iov++, syslog_identifier_full (g->syslog_identifier)); _iovec_set_format_a (iov++, 30, "SYSLOG_PID=%ld", (long) getpid ()); { const LogDesc *diter; int i_domain = _NUM_MAX_FIELDS_SYSLOG_FACILITY; const char *s_domain_1 = NULL; NMLogDomain dom_all = domain; - NMLogDomain dom = dom_all & _nm_logging_enabled_state[level]; + NMLogDomain dom = dom_all & cur_log_state[level]; - for (diter = &global.domain_desc[0]; diter->name; diter++) { + for (diter = &domain_desc[0]; diter->name; diter++) { if (!NM_FLAGS_ANY (dom_all, diter->num)) continue; @@ -690,7 +784,7 @@ _nm_log_impl (const char *file, if (NM_FLAGS_ANY (dom, diter->num)) { if (i_domain > 0) { /* SYSLOG_FACILITY is specified multiple times for each domain that is actually enabled. */ - _iovec_set_format_a (iov++, _MAX_LEN (30, diter->name), "SYSLOG_FACILITY=%s", diter->name); + _iovec_set_format_str_a (iov++, 30, "SYSLOG_FACILITY=%s", diter->name); i_domain--; } dom &= ~diter->num; @@ -701,9 +795,9 @@ _nm_log_impl (const char *file, if (s_domain_all) _iovec_set (iov++, s_domain_all->str, s_domain_all->len); else - _iovec_set_format_a (iov++, _MAX_LEN (30, s_domain_1), "NM_LOG_DOMAINS=%s", s_domain_1); + _iovec_set_format_str_a (iov++, 30, "NM_LOG_DOMAINS=%s", s_domain_1); } - _iovec_set_format_a (iov++, _MAX_LEN (15, global.level_desc[level].name), "NM_LOG_LEVEL=%s", global.level_desc[level].name); + _iovec_set_format_str_a (iov++, 15, "NM_LOG_LEVEL=%s", level_desc[level].name); if (func) _iovec_set_format (iov++, iov_free++, "CODE_FUNC=%s", func); _iovec_set_format (iov++, iov_free++, "CODE_FILE=%s", file ?: ""); @@ -728,18 +822,41 @@ _nm_log_impl (const char *file, break; #endif case LOG_BACKEND_SYSLOG: - syslog (global.level_desc[level].syslog_level, - MESSAGE_FMT, MESSAGE_ARG (global, tv, msg)); + syslog (level_desc[level].syslog_level, + MESSAGE_FMT, MESSAGE_ARG (g->prefix, tv, msg)); break; default: - g_log (syslog_identifier_domain (&global), global.level_desc[level].g_log_level, - MESSAGE_FMT, MESSAGE_ARG (global, tv, msg)); + g_log (syslog_identifier_domain (g->syslog_identifier), level_desc[level].g_log_level, + MESSAGE_FMT, MESSAGE_ARG (g->prefix, tv, msg)); break; } g_free (msg); - errno = errno_saved; + errno = errsv; +} + +/*****************************************************************************/ + +void +_nm_utils_monotonic_timestamp_initialized (const struct timespec *tp, + gint64 offset_sec, + gboolean is_boottime) +{ + NM_ASSERT_ON_MAIN_THREAD (); + + if (_nm_logging_enabled_lockfree (LOGL_DEBUG, LOGD_CORE)) { + time_t now = time (NULL); + struct tm tm; + char s[255]; + + strftime (s, sizeof (s), "%Y-%m-%d %H:%M:%S", localtime_r (&now, &tm)); + nm_log_dbg (LOGD_CORE, "monotonic timestamp started counting 1.%09ld seconds ago with " + "an offset of %lld.0 seconds to %s (local time is %s)", + tp->tv_nsec, + (long long) -offset_sec, + is_boottime ? "CLOCK_BOOTTIME" : "CLOCK_MONOTONIC", s); + } } /*****************************************************************************/ @@ -774,10 +891,14 @@ nm_log_handler (const char *log_domain, break; } - if (global.debug_stderr) - g_printerr ("%s%s\n", global.prefix, message ?: ""); + /* we don't need any locking here. The glib log handler gets only registered + * once during nm_logging_init() and the global data is not modified afterwards. */ + nm_assert (gl.imm.init_done); - switch (global.log_backend) { + if (gl.imm.debug_stderr) + g_printerr ("%s%s\n", gl.imm.prefix, message ?: ""); + + switch (gl.imm.log_backend) { #if SYSTEMD_JOURNAL case LOG_BACKEND_JOURNAL: { @@ -787,8 +908,8 @@ nm_log_handler (const char *log_domain, boottime = nm_utils_monotonic_timestamp_as_boottime (now, 1); sd_journal_send ("PRIORITY=%d", syslog_priority, - "MESSAGE=%s%s", global.prefix, message ?: "", - syslog_identifier_full (&global), + "MESSAGE=%s%s", gl.imm.prefix, message ?: "", + syslog_identifier_full (gl.imm.syslog_identifier), "SYSLOG_PID=%ld", (long) getpid (), "SYSLOG_FACILITY=GLIB", "GLIB_DOMAIN=%s", log_domain ?: "", @@ -800,7 +921,7 @@ nm_log_handler (const char *log_domain, break; #endif default: - syslog (syslog_priority, "%s%s", global.prefix, message ?: ""); + syslog (syslog_priority, "%s%s", gl.imm.prefix, message ?: ""); break; } } @@ -808,44 +929,63 @@ nm_log_handler (const char *log_domain, gboolean nm_logging_syslog_enabled (void) { - return global.uses_syslog; + NM_ASSERT_ON_MAIN_THREAD (); + + return gl.imm.uses_syslog; } void -nm_logging_set_prefix (const char *format, ...) +nm_logging_init_pre (const char *syslog_identifier, + char *prefix_take) { - char *prefix; - va_list ap; + /* this function may be called zero or one times, and only + * - on the main thread + * - not after nm_logging_init(). */ + + NM_ASSERT_ON_MAIN_THREAD (); - /* prefix can only be set once, to a non-empty string. Also, after - * nm_logging_syslog_openlog() the prefix cannot be set either. */ - if (global.log_backend != LOG_BACKEND_GLIB) + if (gl.imm.init_pre_done) g_return_if_reached (); - if (global.prefix[0]) + + if (gl.imm.init_done) g_return_if_reached (); - va_start (ap, format); - prefix = g_strdup_vprintf (format, ap); - va_end (ap); + if (!_syslog_identifier_valid_domain (syslog_identifier)) + g_return_if_reached (); - if (!prefix || !prefix[0]) + if (!prefix_take || !prefix_take[0]) g_return_if_reached (); + G_LOCK (log); + + gl.mut.init_pre_done = TRUE; + + gl.mut.syslog_identifier = g_strdup_printf ("SYSLOG_IDENTIFIER=%s", syslog_identifier); + nm_assert (_syslog_identifier_assert (gl.imm.syslog_identifier)); + /* we pass the allocated string on and never free it. */ - global.prefix = prefix; + gl.mut.prefix = prefix_take; + + G_UNLOCK (log); } void -nm_logging_syslog_openlog (const char *logging_backend, gboolean debug) +nm_logging_init (const char *logging_backend, gboolean debug) { gboolean fetch_monotonic_timestamp = FALSE; gboolean obsolete_debug_backend = FALSE; + LogBackend x_log_backend; + + /* this function may be called zero or one times, and only on the + * main thread. */ + + NM_ASSERT_ON_MAIN_THREAD (); nm_assert (NM_IN_STRSET (""NM_CONFIG_DEFAULT_LOGGING_BACKEND, NM_LOG_CONFIG_BACKEND_JOURNAL, NM_LOG_CONFIG_BACKEND_SYSLOG)); - if (global.log_backend != LOG_BACKEND_GLIB) + if (gl.imm.init_done) g_return_if_reached (); if (!logging_backend) @@ -862,26 +1002,36 @@ nm_logging_syslog_openlog (const char *logging_backend, gboolean debug) obsolete_debug_backend = TRUE; } + + G_LOCK (log); + #if SYSTEMD_JOURNAL if (!nm_streq (logging_backend, NM_LOG_CONFIG_BACKEND_SYSLOG)) { - global.log_backend = LOG_BACKEND_JOURNAL; - global.uses_syslog = TRUE; - global.debug_stderr = debug; + x_log_backend = LOG_BACKEND_JOURNAL; + + /* We only log the monotonic-timestamp with structured logging (journal). + * Only in this case, fetch the timestamp. */ fetch_monotonic_timestamp = TRUE; } else #endif { - global.log_backend = LOG_BACKEND_SYSLOG; - global.uses_syslog = TRUE; - global.debug_stderr = debug; - openlog (syslog_identifier_domain (&global), LOG_PID, LOG_DAEMON); + x_log_backend = LOG_BACKEND_SYSLOG; + openlog (syslog_identifier_domain (gl.imm.syslog_identifier), LOG_PID, LOG_DAEMON); } - g_log_set_handler (syslog_identifier_domain (&global), + gl.mut.init_done = TRUE; + gl.mut.log_backend = x_log_backend; + gl.mut.uses_syslog = TRUE; + gl.mut.debug_stderr = debug; + + g_log_set_handler (syslog_identifier_domain (gl.imm.syslog_identifier), G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION, nm_log_handler, NULL); + G_UNLOCK (log); + + if (fetch_monotonic_timestamp) { /* ensure we read a monotonic timestamp. Reading the timestamp the first * time causes a logging message. We don't want to do that during _nm_log_impl. */ |