pipewire/spa/plugins/support/journal.c
Pauli Virtanen ac35ecf329 journal: prepend code location to messages at debug log levels
Debug and trace log messages are often written based on the stderr
logging, where code location is always visible.

journalctl does not show the code location without extra tricks,
which makes user-submitted debug logs from journal more cryptic.

Make journal log more similar to stderr logs by prepending the code
location and log level in the log message when the log topic
level is >= DEBUG.
2024-04-28 16:02:28 +03:00

329 lines
8.1 KiB
C

/* Spa */
/* SPDX-FileCopyrightText: Copyright © 2020 Sergey Bugaev */
/* SPDX-License-Identifier: MIT */
#include "config.h"
#include <stddef.h>
#include <unistd.h>
#include <string.h>
#include <errno.h>
#include <stdio.h>
#include <limits.h>
#include <syslog.h>
#include <sys/stat.h>
#include <spa/support/log.h>
#include <spa/support/plugin.h>
#include <spa/utils/type.h>
#include <spa/utils/names.h>
#include <spa/utils/string.h>
#include <systemd/sd-journal.h>
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT &log_topic
SPA_LOG_TOPIC_DEFINE_STATIC(log_topic, "spa.journal");
#define DEFAULT_LOG_LEVEL SPA_LOG_LEVEL_INFO
struct impl {
struct spa_handle handle;
struct spa_log log;
/* if non-null, we'll additionally forward all logging to there */
struct spa_log *chain_log;
};
static SPA_PRINTF_FUNC(7,0) void
impl_log_logtv(void *object,
enum spa_log_level level,
const struct spa_log_topic *topic,
const char *file,
int line,
const char *func,
const char *fmt,
va_list args)
{
static const char * const levels[] = { "-", "E", "W", "I", "D", "T", "*T*" };
struct impl *impl = object;
char line_buffer[32];
char file_buffer[strlen("CODE_FILE=") + strlen(file) + 1];
char message_buffer[LINE_MAX];
int priority;
size_t sz = 0;
if (impl->chain_log != NULL) {
va_list args_copy;
va_copy(args_copy, args);
impl->chain_log->level = impl->log.level;
spa_log_logtv(impl->chain_log,
level, topic,
file, line, func, fmt, args_copy);
va_end(args_copy);
}
/* convert SPA log level to syslog priority */
switch (level) {
case SPA_LOG_LEVEL_ERROR:
priority = LOG_ERR;
break;
case SPA_LOG_LEVEL_WARN:
priority = LOG_WARNING;
break;
case SPA_LOG_LEVEL_INFO:
priority = LOG_INFO;
break;
case SPA_LOG_LEVEL_DEBUG:
case SPA_LOG_LEVEL_TRACE:
default:
priority = LOG_DEBUG;
break;
}
if (spa_log_level_topic_enabled(&impl->log, topic, SPA_LOG_LEVEL_DEBUG)) {
const char *lev = levels[SPA_CLAMP(level, 0u, SPA_N_ELEMENTS(levels) - 1u)];
const char *tp = topic ? topic->topic : "";
if (file && func) {
const char *f = strrchr(file, '/');
f = f ? f+1 : file;
sz = spa_scnprintf(message_buffer, sizeof(message_buffer),
"%s %s%s[%s:%d:%s]: ",
lev, tp, topic ? " " : "",
f, line, func);
} else {
sz = spa_scnprintf(message_buffer, sizeof(message_buffer),
"%s %s%s", lev, tp, topic ? ": " : "");
}
} else if (topic) {
sz = spa_scnprintf(message_buffer, sizeof(message_buffer),
"%s: ", topic->topic);
}
/* we'll be using the low-level journal API, which expects us to provide
* the location explicitly. line and file are to be passed as preformatted
* entries, whereas the function name is passed as-is, and converted into
* a field inside sd_journal_send_with_location(). */
snprintf(line_buffer, sizeof(line_buffer), "CODE_LINE=%d", line);
snprintf(file_buffer, sizeof(file_buffer), "CODE_FILE=%s", file);
vsnprintf(message_buffer + sz, sizeof(message_buffer) - sz, fmt, args);
sd_journal_send_with_location(file_buffer, line_buffer, func,
"MESSAGE=%s", message_buffer,
"PRIORITY=%i", priority,
#ifdef HAVE_GETTID
"TID=%jd", (intmax_t) gettid(),
#endif
NULL);
}
static SPA_PRINTF_FUNC(6,7) void
impl_log_log(void *object,
enum spa_log_level level,
const char *file,
int line,
const char *func,
const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
impl_log_logtv(object, level, NULL, file, line, func, fmt, args);
va_end(args);
}
static SPA_PRINTF_FUNC(6,0) void
impl_log_logv(void *object,
enum spa_log_level level,
const char *file,
int line,
const char *func,
const char *fmt,
va_list args)
{
impl_log_logtv(object, level, NULL, file, line, func, fmt, args);
}
static SPA_PRINTF_FUNC(7,8) void
impl_log_logt(void *object,
enum spa_log_level level,
const struct spa_log_topic *topic,
const char *file,
int line,
const char *func,
const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
impl_log_logtv(object, level, topic, file, line, func, fmt, args);
va_end(args);
}
static const struct spa_log_methods impl_log = {
SPA_VERSION_LOG_METHODS,
.log = impl_log_log,
.logv = impl_log_logv,
.logt = impl_log_logt,
.logtv = impl_log_logtv,
};
static int impl_get_interface(struct spa_handle *handle, const char *type, void **interface)
{
struct impl *this;
spa_return_val_if_fail(handle != NULL, -EINVAL);
spa_return_val_if_fail(interface != NULL, -EINVAL);
this = (struct impl *) handle;
if (spa_streq(type, SPA_TYPE_INTERFACE_Log))
*interface = &this->log;
else
return -ENOENT;
return 0;
}
static int impl_clear(struct spa_handle *handle)
{
struct impl SPA_UNUSED *this;
spa_return_val_if_fail(handle != NULL, -EINVAL);
this = (struct impl *) handle;
return 0;
}
static size_t
impl_get_size(const struct spa_handle_factory *factory,
const struct spa_dict *params)
{
return sizeof(struct impl);
}
/** Determine if our stderr goes straight to the journal */
static int
stderr_is_connected_to_journal(void)
{
const char *journal_stream;
unsigned long long journal_device, journal_inode;
struct stat stderr_stat;
/* when a service's stderr is connected to the journal, systemd sets
* JOURNAL_STREAM in the environment of that service to device:inode
* of its stderr. if the variable is not set, clearly our stderr is
* not connected to the journal */
journal_stream = getenv("JOURNAL_STREAM");
if (journal_stream == NULL)
return 0;
/* if it *is* set, that doesn't immediately mean that *our* stderr
* is (still) connected to the journal. to know for sure, we have to
* compare our actual stderr to the stream systemd has created for
* the service we're a part of */
if (sscanf(journal_stream, "%llu:%llu", &journal_device, &journal_inode) != 2)
return 0;
if (fstat(STDERR_FILENO, &stderr_stat) < 0)
return 0;
return stderr_stat.st_dev == journal_device && stderr_stat.st_ino == journal_inode;
}
static int
impl_init(const struct spa_handle_factory *factory,
struct spa_handle *handle,
const struct spa_dict *info,
const struct spa_support *support,
uint32_t n_support)
{
struct impl *impl;
const char *str;
spa_return_val_if_fail(factory != NULL, -EINVAL);
spa_return_val_if_fail(handle != NULL, -EINVAL);
handle->get_interface = impl_get_interface;
handle->clear = impl_clear;
impl = (struct impl *) handle;
impl->log.iface = SPA_INTERFACE_INIT(
SPA_TYPE_INTERFACE_Log,
SPA_VERSION_LOG,
&impl_log, impl);
impl->log.level = DEFAULT_LOG_LEVEL;
if (info) {
if ((str = spa_dict_lookup(info, SPA_KEY_LOG_LEVEL)) != NULL)
impl->log.level = atoi(str);
}
/* if our stderr goes to the journal, there's no point in logging both
* via the native journal API and by printing to stderr, that would just
* result in message duplication */
if (stderr_is_connected_to_journal())
impl->chain_log = NULL;
else
impl->chain_log = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_Log);
spa_log_debug(&impl->log, "%p: initialized", impl);
return 0;
}
static const struct spa_interface_info impl_interfaces[] = {
{SPA_TYPE_INTERFACE_Log,},
};
static int
impl_enum_interface_info(const struct spa_handle_factory *factory,
const struct spa_interface_info **info,
uint32_t *index)
{
spa_return_val_if_fail(factory != NULL, -EINVAL);
spa_return_val_if_fail(info != NULL, -EINVAL);
spa_return_val_if_fail(index != NULL, -EINVAL);
switch (*index) {
case 0:
*info = &impl_interfaces[*index];
break;
default:
return 0;
}
(*index)++;
return 1;
}
static const struct spa_handle_factory journal_factory = {
SPA_VERSION_HANDLE_FACTORY,
.name = SPA_NAME_SUPPORT_LOG,
.info = NULL,
.get_size = impl_get_size,
.init = impl_init,
.enum_interface_info = impl_enum_interface_info,
};
SPA_LOG_TOPIC_ENUM_DEFINE_REGISTERED;
SPA_EXPORT
int spa_handle_factory_enum(const struct spa_handle_factory **factory, uint32_t *index)
{
spa_return_val_if_fail(factory != NULL, -EINVAL);
spa_return_val_if_fail(index != NULL, -EINVAL);
switch (*index) {
case 0:
*factory = &journal_factory;
break;
default:
return 0;
}
(*index)++;
return 1;
}