/* 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 <dlfcn.h>
#include <syslog.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <sys/wait.h>
#include <sys/stat.h>
#include <strings.h>
#if SYSTEMD_JOURNAL
#define SD_JOURNAL_SUPPRESS_LOCATION
#include <systemd/sd-journal.h>
#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
);
}
}