/* SPDX-License-Identifier: GPL-2.0+ */ /* * Copyright (C) 2006 - 2012 Red Hat, Inc. * Copyright (C) 2006 - 2008 Novell, Inc. */ #include "nm-default.h" #include "nm-logging.h" #include #include #include #include #include #include #include #include #if SYSTEMD_JOURNAL #define SD_JOURNAL_SUPPRESS_LOCATION #include #endif #include "nm-glib-aux/nm-logging-base.h" #include "nm-glib-aux/nm-time-utils.h" #include "nm-errors.h" /*****************************************************************************/ /* 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. */ /*****************************************************************************/ G_STATIC_ASSERT(LOG_EMERG == 0); G_STATIC_ASSERT(LOG_ALERT == 1); G_STATIC_ASSERT(LOG_CRIT == 2); G_STATIC_ASSERT(LOG_ERR == 3); G_STATIC_ASSERT(LOG_WARNING == 4); G_STATIC_ASSERT(LOG_NOTICE == 5); G_STATIC_ASSERT(LOG_INFO == 6); G_STATIC_ASSERT(LOG_DEBUG == 7); /* 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; const char *name; } LogDesc; 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); * * Note: LOGD_VPN_PLUGIN is special and must be disabled for * DEBUG and TRACE levels. */ [LOGL_INFO] = LOGD_DEFAULT, [LOGL_WARN] = LOGD_DEFAULT, [LOGL_ERR] = LOGD_DEFAULT, }; /*****************************************************************************/ 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, NMLogLevel log_level, const NMLogDomain log_state[static _LOGL_N_REAL]); /*****************************************************************************/ static gboolean _syslog_identifier_valid_domain(const char *domain) { char c; if (!domain || !domain[0]) return FALSE; /* we pass the syslog identifier as format string. No funny stuff. */ for (; (c = domain[0]); domain++) { if ((c >= 'a' && c <= 'z') || (c >= 'A' && c <= 'Z') || (c >= '0' && c <= '9') || NM_IN_SET(c, '-', '_')) continue; return FALSE; } return TRUE; } static gboolean _syslog_identifier_assert(const char *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 char *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 char *syslog_identifier) { nm_assert(_syslog_identifier_assert(syslog_identifier)); return &syslog_identifier[0]; } #endif /*****************************************************************************/ static gboolean match_log_level(const char *level, NMLogLevel *out_level, GError **error) { if (_nm_log_parse_level(level, out_level)) return TRUE; g_set_error(error, NM_MANAGER_ERROR, NM_MANAGER_ERROR_UNKNOWN_LOG_LEVEL, _("Unknown log level '%s'"), level); return FALSE; } gboolean nm_logging_setup(const char *level, const char *domains, char **bad_domains, GError **error) { GString * unrecognized = NULL; NMLogDomain cur_log_state[_LOGL_N_REAL]; NMLogDomain new_log_state[_LOGL_N_REAL]; NMLogLevel cur_log_level; NMLogLevel new_log_level; gs_free const char **domains_v = NULL; gsize i_d; 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); 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_log_state); i++) new_log_state[i] = 0; if (level && *level) { if (!match_log_level(level, &new_log_level, error)) return FALSE; if (new_log_level == _LOGL_KEEP) { 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]; } } domains_v = nm_utils_strsplit_set(domains, ", "); for (i_d = 0; domains_v && domains_v[i_d]; i_d++) { const char * s = domains_v[i_d]; const char * p; const LogDesc *diter; NMLogLevel domain_log_level; NMLogDomain bits; /* LOGD_VPN_PLUGIN is protected, that is, when setting ALL or DEFAULT, * it does not enable the verbose levels DEBUG and TRACE, because that * may expose sensitive data. */ NMLogDomain protect = LOGD_NONE; p = strchr(s, ':'); if (p) { *((char *) p) = '\0'; if (!match_log_level(p + 1, &domain_log_level, error)) return FALSE; } else domain_log_level = new_log_level; bits = 0; if (domains_free) { /* The caller didn't provide any domains to set (`nmcli general logging level DEBUG`). * We reset all domains that were previously set, but we still want to protect * VPN_PLUGIN domain. */ protect = LOGD_VPN_PLUGIN; } /* Check for combined domains */ if (!g_ascii_strcasecmp(s, LOGD_ALL_STRING)) { bits = LOGD_ALL; protect = LOGD_VPN_PLUGIN; } else if (!g_ascii_strcasecmp(s, LOGD_DEFAULT_STRING)) { bits = LOGD_DEFAULT; protect = LOGD_VPN_PLUGIN; } else if (!g_ascii_strcasecmp(s, LOGD_DHCP_STRING)) bits = LOGD_DHCP; else if (!g_ascii_strcasecmp(s, LOGD_IP_STRING)) bits = LOGD_IP; /* Check for compatibility domains */ else if (!g_ascii_strcasecmp(s, "HW")) bits = LOGD_PLATFORM; else if (!g_ascii_strcasecmp(s, "WIMAX")) continue; else { for (diter = &domain_desc[0]; diter->name; diter++) { if (!g_ascii_strcasecmp(diter->name, s)) { bits = diter->num; break; } } if (!bits) { if (!bad_domains) { g_set_error(error, NM_MANAGER_ERROR, NM_MANAGER_ERROR_UNKNOWN_LOG_DOMAIN, _("Unknown log domain '%s'"), s); return FALSE; } if (unrecognized) g_string_append(unrecognized, ", "); else unrecognized = g_string_new(NULL); g_string_append(unrecognized, s); continue; } } if (domain_log_level == _LOGL_KEEP) { 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_log_state); i++) { if (i < domain_log_level) new_log_state[i] &= ~bits; else { new_log_state[i] |= bits; if ((protect & bits) && i < LOGL_INFO) new_log_state[i] &= ~protect; } } } } nm_clear_g_free(&gl_main.logging_domains_to_string); 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_log_state); i++) _nm_logging_enabled_state[i] = new_log_state[i]; G_UNLOCK(log); if (had_platform_debug && !_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. */ _nm_logging_clear_platform_logging_cache(); } if (unrecognized) *bad_domains = g_string_free(unrecognized, FALSE); return TRUE; } const char * nm_logging_level_to_string(void) { NM_ASSERT_ON_MAIN_THREAD(); return level_desc[gl.imm.log_level].name; } const char * nm_logging_all_levels_to_string(void) { static GString *str; if (G_UNLIKELY(!str)) { int i; str = g_string_new(NULL); for (i = 0; i < G_N_ELEMENTS(level_desc); i++) { if (str->len) g_string_append_c(str, ','); g_string_append(str, level_desc[i].name); } } return str->str; } const char * nm_logging_domains_to_string(void) { 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 gl_main.logging_domains_to_string; } static char * _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() 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 = &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 & log_state[LOGL_ERR])) continue; if (str->len) g_string_append_c(str, ','); g_string_append(str, diter->name); if (!include_level_override) continue; /* Check if it's logging at a lower level than the default. */ 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 & 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; } } } } return g_string_free(str, FALSE); } static char _all_logging_domains_to_str[273]; const char * nm_logging_all_domains_to_string(void) { static const char *volatile str = NULL; const char *s; again: s = g_atomic_pointer_get(&str); if (G_UNLIKELY(!s)) { static gsize once = 0; const LogDesc *diter; gsize buf_l; char * buf_p; if (!g_once_init_enter(&once)) goto again; buf_p = _all_logging_domains_to_str; buf_l = sizeof(_all_logging_domains_to_str); nm_utils_strbuf_append_str(&buf_p, &buf_l, LOGD_DEFAULT_STRING); for (diter = &domain_desc[0]; diter->name; diter++) { nm_utils_strbuf_append_c(&buf_p, &buf_l, ','); nm_utils_strbuf_append_str(&buf_p, &buf_l, diter->name); if (diter->num == LOGD_DHCP6) nm_utils_strbuf_append_str(&buf_p, &buf_l, "," LOGD_DHCP_STRING); else if (diter->num == LOGD_IP6) nm_utils_strbuf_append_str(&buf_p, &buf_l, "," LOGD_IP_STRING); } nm_utils_strbuf_append_str(&buf_p, &buf_l, LOGD_ALL_STRING); /* Did you modify the logging domains (or their names)? Adjust the size of * _all_logging_domains_to_str buffer above to have the exact size. */ nm_assert(strlen(_all_logging_domains_to_str) == sizeof(_all_logging_domains_to_str) - 1); nm_assert(buf_l == 1); s = _all_logging_domains_to_str; g_atomic_pointer_set(&str, s); g_once_init_leave(&once, 1); } return s; } /** * nm_logging_get_level: * @domain: find the lowest enabled logging level for the * given domain. If this is a set of multiple * domains, the most verbose level will be returned. * * Returns: the lowest (most verbose) logging level for the * give @domain, or %_LOGL_OFF if it is disabled. **/ NMLogLevel nm_logging_get_level(NMLogDomain domain) { NMLogLevel sl = _LOGL_OFF; G_STATIC_ASSERT(LOGL_TRACE == 0); while (sl > LOGL_TRACE && _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) { iov->iov_base = (void *) str; iov->iov_len = len; } static void _iovec_set_string(struct iovec *iov, const char *str) { _iovec_set(iov, str, strlen(str)); } #define _iovec_set_string_literal(iov, str) _iovec_set((iov), "" str "", NM_STRLEN(str)) _nm_printf(3, 4) static void _iovec_set_format(struct iovec *iov, char ** iov_free, const char * format, ...) { va_list ap; char * str; va_start(ap, format); str = g_strdup_vprintf(format, ap); va_end(ap); _iovec_set_string(iov, str); *iov_free = str; } #define _iovec_set_format_a(iov, reserve_extra, format, ...) \ G_STMT_START \ { \ const gsize _size = (reserve_extra) + (NM_STRLEN(format) + 3); \ 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 == 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, const char *ifname, const char *conn_uuid, const char *fmt, ...) { va_list args; char * msg; GTimeVal tv; 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; } (void) cur_log_state; errsv = errno; /* Make sure that %m maps to the specified error */ if (error != 0) { if (error < 0) error = -error; errno = error; } va_start(args, fmt); msg = g_strdup_vprintf(fmt, args); va_end(args); #define MESSAGE_FMT "%s%-7s [%ld.%04ld] %s" #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 (g->debug_stderr) g_printerr(MESSAGE_FMT "\n", MESSAGE_ARG(g->prefix, tv, msg)); switch (g->log_backend) { #if SYSTEMD_JOURNAL case LOG_BACKEND_JOURNAL: { gint64 now, boottime; struct iovec iov_data[15]; struct iovec * iov = iov_data; char * iov_free_data[5]; char ** iov_free = iov_free_data; const LogDesc *diter; NMLogDomain dom_all; char s_log_domains_buf[NM_STRLEN("NM_LOG_DOMAINS=") + sizeof(_all_logging_domains_to_str)]; char *s_log_domains; gsize l_log_domains; now = nm_utils_get_monotonic_timestamp_nsec(); 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(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()); dom_all = domain; s_log_domains = s_log_domains_buf; l_log_domains = sizeof(s_log_domains_buf); nm_utils_strbuf_append_str(&s_log_domains, &l_log_domains, "NM_LOG_DOMAINS="); for (diter = &domain_desc[0]; dom_all != 0 && diter->name; diter++) { if (!NM_FLAGS_ANY(dom_all, diter->num)) continue; if (dom_all != domain) nm_utils_strbuf_append_c(&s_log_domains, &l_log_domains, ','); nm_utils_strbuf_append_str(&s_log_domains, &l_log_domains, diter->name); dom_all &= ~diter->num; } nm_assert(l_log_domains > 0); _iovec_set(iov++, s_log_domains_buf, s_log_domains - s_log_domains_buf); G_STATIC_ASSERT_EXPR(LOG_FAC(LOG_DAEMON) == 3); _iovec_set_string_literal(iov++, "SYSLOG_FACILITY=3"); _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 ?: ""); _iovec_set_format_a(iov++, 20, "CODE_LINE=%u", line); _iovec_set_format_a(iov++, 60, "TIMESTAMP_MONOTONIC=%lld.%06lld", (long long) (now / NM_UTILS_NSEC_PER_SEC), (long long) ((now % NM_UTILS_NSEC_PER_SEC) / 1000)); _iovec_set_format_a(iov++, 60, "TIMESTAMP_BOOTTIME=%lld.%06lld", (long long) (boottime / NM_UTILS_NSEC_PER_SEC), (long long) ((boottime % NM_UTILS_NSEC_PER_SEC) / 1000)); if (error != 0) _iovec_set_format_a(iov++, 30, "ERRNO=%d", error); if (ifname) _iovec_set_format(iov++, iov_free++, "NM_DEVICE=%s", ifname); if (conn_uuid) _iovec_set_format(iov++, iov_free++, "NM_CONNECTION=%s", conn_uuid); nm_assert(iov <= &iov_data[G_N_ELEMENTS(iov_data)]); nm_assert(iov_free <= &iov_free_data[G_N_ELEMENTS(iov_free_data)]); sd_journal_sendv(iov_data, iov - iov_data); for (; --iov_free >= iov_free_data;) g_free(*iov_free); } break; #endif case LOG_BACKEND_SYSLOG: syslog(level_desc[level].syslog_level, MESSAGE_FMT, MESSAGE_ARG(g->prefix, tv, msg)); break; default: 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 = 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); } } /*****************************************************************************/ static void nm_log_handler(const char *log_domain, GLogLevelFlags level, const char *message, gpointer ignored) { int syslog_priority; switch (level & G_LOG_LEVEL_MASK) { case G_LOG_LEVEL_ERROR: syslog_priority = LOG_CRIT; break; case G_LOG_LEVEL_CRITICAL: syslog_priority = LOG_ERR; break; case G_LOG_LEVEL_WARNING: syslog_priority = LOG_WARNING; break; case G_LOG_LEVEL_MESSAGE: syslog_priority = LOG_NOTICE; break; case G_LOG_LEVEL_DEBUG: syslog_priority = LOG_DEBUG; break; case G_LOG_LEVEL_INFO: default: syslog_priority = LOG_INFO; 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 ?: ""); switch (gl.imm.log_backend) { #if SYSTEMD_JOURNAL case LOG_BACKEND_JOURNAL: { gint64 now, boottime; now = nm_utils_get_monotonic_timestamp_nsec(); boottime = nm_utils_monotonic_timestamp_as_boottime(now, 1); sd_journal_send("PRIORITY=%d", syslog_priority, "MESSAGE=%s%s", gl.imm.prefix, message ?: "", syslog_identifier_full(gl.imm.syslog_identifier), "SYSLOG_PID=%ld", (long) getpid(), "SYSLOG_FACILITY=3", "GLIB_DOMAIN=%s", log_domain ?: "", "GLIB_LEVEL=%d", (int) (level & G_LOG_LEVEL_MASK), "TIMESTAMP_MONOTONIC=%lld.%06lld", (long long) (now / NM_UTILS_NSEC_PER_SEC), (long long) ((now % NM_UTILS_NSEC_PER_SEC) / 1000), "TIMESTAMP_BOOTTIME=%lld.%06lld", (long long) (boottime / NM_UTILS_NSEC_PER_SEC), (long long) ((boottime % NM_UTILS_NSEC_PER_SEC) / 1000), NULL); } break; #endif default: syslog(syslog_priority, "%s%s", gl.imm.prefix, message ?: ""); break; } } gboolean nm_logging_syslog_enabled(void) { NM_ASSERT_ON_MAIN_THREAD(); return gl.imm.uses_syslog; } void nm_logging_init_pre(const char *syslog_identifier, char *prefix_take) { /* 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(); if (gl.imm.init_pre_done) g_return_if_reached(); if (gl.imm.init_done) g_return_if_reached(); if (!_syslog_identifier_valid_domain(syslog_identifier)) g_return_if_reached(); 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. */ gl.mut.prefix = prefix_take; G_UNLOCK(log); } void 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 (gl.imm.init_done) g_return_if_reached(); if (!logging_backend) logging_backend = "" NM_CONFIG_DEFAULT_LOGGING_BACKEND; if (nm_streq(logging_backend, NM_LOG_CONFIG_BACKEND_DEBUG)) { /* "debug" was wrongly documented as a valid logging backend. It makes no sense however, * because printing to stderr only makes sense when not demonizing. Whether to daemonize * is only controlled via command line arguments (--no-daemon, --debug) and not via the * logging backend from configuration. * * Fall back to the default. */ logging_backend = "" NM_CONFIG_DEFAULT_LOGGING_BACKEND; obsolete_debug_backend = TRUE; } G_LOCK(log); #if SYSTEMD_JOURNAL if (!nm_streq(logging_backend, NM_LOG_CONFIG_BACKEND_SYSLOG)) { 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 { 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. */ nm_utils_get_monotonic_timestamp_nsec(); } if (obsolete_debug_backend) nm_log_dbg(LOGD_CORE, "config: ignore deprecated logging backend 'debug', fallback to '%s'", logging_backend); if (nm_streq(logging_backend, NM_LOG_CONFIG_BACKEND_SYSLOG)) { /* good */ } else if (nm_streq(logging_backend, NM_LOG_CONFIG_BACKEND_JOURNAL)) { #if !SYSTEMD_JOURNAL nm_log_warn(LOGD_CORE, "config: logging backend 'journal' is not available, fallback to 'syslog'"); #endif } else { nm_log_warn(LOGD_CORE, "config: invalid logging backend '%s', fallback to '%s'", logging_backend, #if SYSTEMD_JOURNAL NM_LOG_CONFIG_BACKEND_JOURNAL #else NM_LOG_CONFIG_BACKEND_SYSLOG #endif ); } }