diff options
author | Thomas Haller <thaller@redhat.com> | 2019-01-16 16:40:45 +0100 |
---|---|---|
committer | Thomas Haller <thaller@redhat.com> | 2019-02-05 08:18:08 +0100 |
commit | fcfd4f4ff29b1399da5e88da32787725a8d193a8 (patch) | |
tree | 99719a035a5a9d66db622f81ee576041ee5ea21a | |
parent | 834c092b51d6bb1f4e0ef4c1eedb018acd9a0b3b (diff) | |
download | NetworkManager-fcfd4f4ff29b1399da5e88da32787725a8d193a8.tar.gz |
logging: make nm-logging thread-safe
NetworkManager is single-threaded and uses a mainloop.
However, sometimes we may need multiple threads. For example, we will
need to write sysctl values asynchronously, using the glib thread-pool.
For that to work, we also need to switch the network-namespace of the
thread-pool thread. We want to use NMPNetns for that. Hence it's better
to have NMPNetns thread-safe, instead of coming up with a duplicate
implementation. But NMPNetns may want to log, so we also need nm-logging
thread-safe.
In general, code under "shared/nm-utils" and nm-logging should be usable
from multiple threads. It's simpler to make this code thread-safe than
re-implementing it. Also, it's a bad limitation to be unable to log
from other threads. If there is an error, the best we can often do is to
log about it.
Make nm-logging thread-safe. Actually, we only need to be able to log
from multiple threads. We don't need to setup or configure logging from
multiple threads. This restriction allows us to access logging from the
main-thread without any thread-synchronization (because all changes in
the logging setup are also done from the main-thread).
So, while logging from other threads requires a mutex, logging from the
main-thread is lock-free.
-rw-r--r-- | shared/nm-utils/nm-logging-fwd.h | 8 | ||||
-rw-r--r-- | shared/systemd/nm-logging-stub.c | 6 | ||||
-rw-r--r-- | shared/systemd/sd-adapt-shared/nm-sd-adapt-shared.h | 4 | ||||
-rw-r--r-- | src/nm-logging.c | 200 | ||||
-rw-r--r-- | src/nm-logging.h | 31 | ||||
-rw-r--r-- | src/tests/test-systemd.c | 6 |
6 files changed, 191 insertions, 64 deletions
diff --git a/shared/nm-utils/nm-logging-fwd.h b/shared/nm-utils/nm-logging-fwd.h index 303d59514c..900dfff812 100644 --- a/shared/nm-utils/nm-logging-fwd.h +++ b/shared/nm-utils/nm-logging-fwd.h @@ -94,18 +94,20 @@ typedef enum { /*< skip >*/ _LOGL_N, /* the number of logging levels including "OFF" */ } NMLogLevel; -gboolean _nm_log_enabled (NMLogLevel level, - NMLogDomain domain); +gboolean _nm_log_enabled_impl (gboolean mt_require_locking, + NMLogLevel level, + NMLogDomain domain); void _nm_log_impl (const char *file, guint line, const char *func, + gboolean mt_require_locking, NMLogLevel level, NMLogDomain domain, int error, const char *ifname, const char *con_uuid, const char *fmt, - ...) _nm_printf (9, 10); + ...) _nm_printf (10, 11); #endif /* __NM_LOGGING_DEFINES_H__ */ diff --git a/shared/systemd/nm-logging-stub.c b/shared/systemd/nm-logging-stub.c index 80d4360783..5be69b4bf3 100644 --- a/shared/systemd/nm-logging-stub.c +++ b/shared/systemd/nm-logging-stub.c @@ -24,8 +24,9 @@ /*****************************************************************************/ gboolean -_nm_log_enabled (NMLogLevel level, - NMLogDomain domain) +_nm_log_enabled_impl (gboolean mt_require_locking, + NMLogLevel level, + NMLogDomain domain) { return FALSE; } @@ -34,6 +35,7 @@ void _nm_log_impl (const char *file, guint line, const char *func, + gboolean mt_require_locking, NMLogLevel level, NMLogDomain domain, int error, diff --git a/shared/systemd/sd-adapt-shared/nm-sd-adapt-shared.h b/shared/systemd/sd-adapt-shared/nm-sd-adapt-shared.h index 905e45c0e1..f68144d896 100644 --- a/shared/systemd/sd-adapt-shared/nm-sd-adapt-shared.h +++ b/shared/systemd/sd-adapt-shared/nm-sd-adapt-shared.h @@ -54,10 +54,10 @@ _nm_log_get_max_level_realm (void) const int _nm_e = (error); \ const NMLogLevel _nm_l = _slog_level_to_nm ((level)); \ \ - if (_nm_log_enabled (_nm_l, LOGD_SYSTEMD)) { \ + if (_nm_log_enabled_impl (!(NM_THREAD_SAFE_ON_MAIN_THREAD), _nm_l, LOGD_SYSTEMD)) { \ const char *_nm_location = strrchr ((""file), '/'); \ \ - _nm_log_impl (_nm_location ? _nm_location + 1 : (""file), (line), (func), _nm_l, LOGD_SYSTEMD, _nm_e, NULL, NULL, ("%s"format), "libsystemd: ", ## __VA_ARGS__); \ + _nm_log_impl (_nm_location ? _nm_location + 1 : (""file), (line), (func), !(NM_THREAD_SAFE_ON_MAIN_THREAD), _nm_l, LOGD_SYSTEMD, _nm_e, NULL, NULL, ("%s"format), "libsystemd: ", ## __VA_ARGS__); \ } \ (_nm_e > 0 ? -_nm_e : _nm_e); \ }) diff --git a/src/nm-logging.c b/src/nm-logging.c index 241575892b..8388e603e2 100644 --- a/src/nm-logging.c +++ b/src/nm-logging.c @@ -44,6 +44,32 @@ /*****************************************************************************/ +/* 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)); @@ -106,6 +132,8 @@ typedef struct { /*****************************************************************************/ +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 = { }; @@ -272,8 +300,10 @@ 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 = gl.imm.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; @@ -284,25 +314,28 @@ nm_logging_setup (const char *level, g_return_val_if_fail (!bad_domains || !*bad_domains, FALSE); g_return_val_if_fail (!error || !*error, FALSE); - /* domains */ + 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, - gl.imm.log_level, - _nm_logging_enabled_state); + 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 = gl.imm.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]; } } @@ -383,17 +416,17 @@ 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; } } } @@ -402,14 +435,18 @@ nm_logging_setup (const char *level, 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); + + G_LOCK (log); gl.mut.log_level = new_log_level; - for (i = 0; i < G_N_ELEMENTS (new_logging); i++) - _nm_logging_enabled_state[i] = new_logging[i]; + 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_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. */ @@ -425,6 +462,8 @@ nm_logging_setup (const char *level, const char * nm_logging_level_to_string (void) { + NM_ASSERT_ON_MAIN_THREAD (); + return level_desc[gl.imm.log_level].name; } @@ -470,8 +509,8 @@ _domains_to_string (gboolean include_level_override, GString *str; int i; - /* We don't just return g_strdup (gl.imm.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); @@ -546,16 +585,29 @@ 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_log_enabled (NMLogLevel level, - NMLogDomain domain) +_nm_logging_enabled_locking (NMLogLevel level, + NMLogDomain domain) { - return nm_logging_enabled (level, 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 @@ -618,6 +670,7 @@ void _nm_log_impl (const char *file, guint line, const char *func, + gboolean mt_require_locking, NMLogLevel level, NMLogDomain domain, int error, @@ -630,12 +683,34 @@ _nm_log_impl (const char *file, char *msg; GTimeVal tv; int errno_saved; + 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 ((guint) level >= G_N_ELEMENTS (_nm_logging_enabled_state)) - g_return_if_reached (); - - if (!(_nm_logging_enabled_state[level] & domain)) - return; + (void) cur_log_state; errno_saved = errno; @@ -651,8 +726,8 @@ _nm_log_impl (const char *file, va_end (args); #define MESSAGE_FMT "%s%-7s [%ld.%04ld] %s" -#define MESSAGE_ARG(g, tv, msg) \ - (g)->prefix, \ +#define MESSAGE_ARG(prefix, tv, msg) \ + prefix, \ level_desc[level].level_str, \ (tv).tv_sec, \ ((tv).tv_usec / 100), \ @@ -660,10 +735,10 @@ _nm_log_impl (const char *file, g_get_current_time (&tv); - if (gl.imm.debug_stderr) - g_printerr (MESSAGE_FMT"\n", MESSAGE_ARG (&gl.imm, tv, msg)); + if (g->debug_stderr) + g_printerr (MESSAGE_FMT"\n", MESSAGE_ARG (g->prefix, tv, msg)); - switch (gl.imm.log_backend) { + switch (g->log_backend) { #if SYSTEMD_JOURNAL case LOG_BACKEND_JOURNAL: { @@ -679,15 +754,15 @@ _nm_log_impl (const char *file, boottime = nm_utils_monotonic_timestamp_as_boottime (now, 1); _iovec_set_format_a (iov++, 30, "PRIORITY=%d", level_desc[level].syslog_level); - _iovec_set_format (iov++, iov_free++, "MESSAGE="MESSAGE_FMT, MESSAGE_ARG (&gl.imm, tv, msg)); - _iovec_set_string (iov++, syslog_identifier_full (gl.imm.syslog_identifier)); + _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 = &domain_desc[0]; diter->name; diter++) { if (!NM_FLAGS_ANY (dom_all, diter->num)) @@ -750,11 +825,11 @@ _nm_log_impl (const char *file, #endif case LOG_BACKEND_SYSLOG: syslog (level_desc[level].syslog_level, - MESSAGE_FMT, MESSAGE_ARG (&gl.imm, tv, msg)); + MESSAGE_FMT, MESSAGE_ARG (g->prefix, tv, msg)); break; default: - g_log (syslog_identifier_domain (gl.imm.syslog_identifier), level_desc[level].g_log_level, - MESSAGE_FMT, MESSAGE_ARG (&gl.imm, 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; } @@ -770,7 +845,9 @@ _nm_utils_monotonic_timestamp_initialized (const struct timespec *tp, gint64 offset_sec, gboolean is_boottime) { - if (nm_logging_enabled (LOGL_DEBUG, LOGD_CORE)) { + 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]; @@ -816,6 +893,10 @@ nm_log_handler (const char *log_domain, break; } + /* 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); + if (gl.imm.debug_stderr) g_printerr ("%s%s\n", gl.imm.prefix, message ?: ""); @@ -850,6 +931,8 @@ nm_log_handler (const char *log_domain, gboolean nm_logging_syslog_enabled (void) { + NM_ASSERT_ON_MAIN_THREAD (); + return gl.imm.uses_syslog; } @@ -875,6 +958,8 @@ nm_logging_init_pre (const char *syslog_identifier, 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); @@ -882,6 +967,8 @@ nm_logging_init_pre (const char *syslog_identifier, /* we pass the allocated string on and never free it. */ gl.mut.prefix = prefix_take; + + G_UNLOCK (log); } void @@ -889,6 +976,7 @@ 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. */ @@ -902,8 +990,6 @@ nm_logging_init (const char *logging_backend, gboolean debug) if (gl.imm.init_done) g_return_if_reached (); - gl.mut.init_done = TRUE; - if (!logging_backend) logging_backend = ""NM_CONFIG_DEFAULT_LOGGING_BACKEND; @@ -918,26 +1004,36 @@ nm_logging_init (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)) { - gl.mut.log_backend = LOG_BACKEND_JOURNAL; - gl.mut.uses_syslog = TRUE; - gl.mut.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 { - gl.mut.log_backend = LOG_BACKEND_SYSLOG; - gl.mut.uses_syslog = TRUE; - gl.mut.debug_stderr = debug; + x_log_backend = LOG_BACKEND_SYSLOG; openlog (syslog_identifier_domain (gl.imm.syslog_identifier), LOG_PID, LOG_DAEMON); } + 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. */ diff --git a/src/nm-logging.h b/src/nm-logging.h index e7b307c23e..a824890a1c 100644 --- a/src/nm-logging.h +++ b/src/nm-logging.h @@ -54,10 +54,12 @@ LOGD_IP_from_af (int addr_family) /* A wrapper for the _nm_log_impl() function that adds call site information. * Contrary to nm_log(), it unconditionally calls the function without * checking whether logging for the given level and domain is enabled. */ -#define _nm_log(level, domain, error, ifname, con_uuid, ...) \ +#define _nm_log_mt(mt_require_locking, level, domain, error, ifname, con_uuid, ...) \ G_STMT_START { \ - _nm_log_impl (__FILE__, __LINE__, \ + _nm_log_impl (__FILE__, \ + __LINE__, \ _NM_LOG_FUNC, \ + (mt_require_locking), \ (level), \ (domain), \ (error), \ @@ -66,6 +68,9 @@ LOGD_IP_from_af (int addr_family) ""__VA_ARGS__); \ } G_STMT_END +#define _nm_log(level, domain, error, ifname, con_uuid, ...) \ + _nm_log_mt (!(NM_THREAD_SAFE_ON_MAIN_THREAD), level, domain, error, ifname, con_uuid, __VA_ARGS__) + /* nm_log() only evaluates its argument list after checking * whether logging for the given level/domain is enabled. */ #define nm_log(level, domain, ifname, con_uuid, ...) \ @@ -138,15 +143,35 @@ _nm_log_ptr_is_debug (NMLogLevel level) const char *nm_logging_level_to_string (void); const char *nm_logging_domains_to_string (void); +/*****************************************************************************/ + extern NMLogDomain _nm_logging_enabled_state[_LOGL_N_REAL]; + static inline gboolean -nm_logging_enabled (NMLogLevel level, NMLogDomain domain) +_nm_logging_enabled_lockfree (NMLogLevel level, NMLogDomain domain) { nm_assert (((guint) level) < G_N_ELEMENTS (_nm_logging_enabled_state)); return (((guint) level) < G_N_ELEMENTS (_nm_logging_enabled_state)) && !!(_nm_logging_enabled_state[level] & domain); } +gboolean _nm_logging_enabled_locking (NMLogLevel level, NMLogDomain domain); + +static inline gboolean +nm_logging_enabled_mt (gboolean mt_require_locking, NMLogLevel level, NMLogDomain domain) +{ + if (mt_require_locking) + return _nm_logging_enabled_locking (level, domain); + + NM_ASSERT_ON_MAIN_THREAD (); + return _nm_logging_enabled_lockfree (level, domain); +} + +#define nm_logging_enabled(level, domain) \ + nm_logging_enabled_mt (!(NM_THREAD_SAFE_ON_MAIN_THREAD), level, domain) + +/*****************************************************************************/ + NMLogLevel nm_logging_get_level (NMLogDomain domain); const char *nm_logging_all_levels_to_string (void); diff --git a/src/tests/test-systemd.c b/src/tests/test-systemd.c index 05e2277665..0c2425255b 100644 --- a/src/tests/test-systemd.c +++ b/src/tests/test-systemd.c @@ -49,8 +49,9 @@ nm_utils_get_monotonic_timestamp_s (void) NMLogDomain _nm_logging_enabled_state[_LOGL_N_REAL]; gboolean -_nm_log_enabled (NMLogLevel level, - NMLogDomain domain) +_nm_log_enabled_impl (gboolean mt_require_locking, + NMLogLevel level, + NMLogDomain domain) { return FALSE; } @@ -59,6 +60,7 @@ void _nm_log_impl (const char *file, guint line, const char *func, + gboolean mt_require_locking, NMLogLevel level, NMLogDomain domain, int error, |