michaelh/zephyr
1
0
Fork 0
Code Releases Activity
zephyr/subsys/logging/log_core.c
Krzysztof Chruscinski 194c0acdfd logging: Add option to have tag which is prepended to all messages 
Tag can be changed at runtime. Feature is enabled by setting
maximum tag length to positive value. Additionally, default
tag can be configured in Kconfig.

Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
2022-01-04 14:57:31 -06:00

1300 lines
29 KiB
C
Raw Blame History

/*
* Copyright (c) 2018 Nordic Semiconductor ASA
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <logging/log_msg.h>
#include "log_list.h"
#include <logging/log.h>
#include <logging/log_backend.h>
#include <logging/log_ctrl.h>
#include <logging/log_output.h>
#include <logging/log_internal.h>
#include <sys/mpsc_pbuf.h>
#include <sys/printk.h>
#include <sys_clock.h>
#include <init.h>
#include <sys/__assert.h>
#include <sys/atomic.h>
#include <ctype.h>
#include <logging/log_frontend.h>
#include <syscall_handler.h>
LOG_MODULE_REGISTER(log);
#ifndef CONFIG_LOG_PRINTK_MAX_STRING_LENGTH
#define CONFIG_LOG_PRINTK_MAX_STRING_LENGTH 0
#endif
#ifndef CONFIG_LOG_PROCESS_THREAD_SLEEP_MS
#define CONFIG_LOG_PROCESS_THREAD_SLEEP_MS 0
#endif
#ifndef CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD
#define CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD 0
#endif
#ifndef CONFIG_LOG_PROCESS_THREAD_STACK_SIZE
#define CONFIG_LOG_PROCESS_THREAD_STACK_SIZE 1
#endif
#ifndef CONFIG_LOG_STRDUP_MAX_STRING
/* Required to suppress compiler warnings related to array subscript above array bounds.
* log_strdup explicitly accesses element with index of (sizeof(log_strdup_buf.buf) - 2).
* Set to 2 because some compilers generate warning on strncpy(dst, src, 0).
*/
#define CONFIG_LOG_STRDUP_MAX_STRING 2
#endif
#ifndef CONFIG_LOG_STRDUP_BUF_COUNT
#define CONFIG_LOG_STRDUP_BUF_COUNT 0
#endif
#ifndef CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS
#define CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS 0
#endif
#ifndef CONFIG_LOG_BUFFER_SIZE
#define CONFIG_LOG_BUFFER_SIZE 4
#endif
struct log_strdup_buf {
atomic_t refcount;
char buf[CONFIG_LOG_STRDUP_MAX_STRING + 1]; /* for termination */
} __aligned(sizeof(uintptr_t));
union log_msgs {
struct log_msg *msg;
union log_msg2_generic *msg2;
};
#define LOG_STRDUP_POOL_BUFFER_SIZE \
(sizeof(struct log_strdup_buf) * CONFIG_LOG_STRDUP_BUF_COUNT)
K_SEM_DEFINE(log_process_thread_sem, 0, 1);
static const char *log_strdup_fail_msg = "<log_strdup alloc failed>";
struct k_mem_slab log_strdup_pool;
static uint8_t __noinit __aligned(sizeof(void *))
log_strdup_pool_buf[LOG_STRDUP_POOL_BUFFER_SIZE];
static struct log_list_t list;
static atomic_t initialized;
static bool panic_mode;
static bool backend_attached;
static atomic_t buffered_cnt;
static atomic_t dropped_cnt;
static k_tid_t proc_tid;
static atomic_t log_strdup_in_use;
static uint32_t log_strdup_max;
static uint32_t log_strdup_longest;
static struct k_timer log_process_thread_timer;
static log_timestamp_t dummy_timestamp(void);
static log_timestamp_get_t timestamp_func = dummy_timestamp;
struct mpsc_pbuf_buffer log_buffer;
static uint32_t __aligned(Z_LOG_MSG2_ALIGNMENT)
buf32[CONFIG_LOG_BUFFER_SIZE / sizeof(int)];
static void notify_drop(const struct mpsc_pbuf_buffer *buffer,
const union mpsc_pbuf_generic *item);
static const struct mpsc_pbuf_buffer_config mpsc_config = {
.buf = (uint32_t *)buf32,
.size = ARRAY_SIZE(buf32),
.notify_drop = notify_drop,
.get_wlen = log_msg2_generic_get_wlen,
.flags = IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW) ?
MPSC_PBUF_MODE_OVERWRITE : 0
};
/* Check that default tag can fit in tag buffer. */
COND_CODE_0(CONFIG_LOG_TAG_MAX_LEN, (),
(BUILD_ASSERT(sizeof(CONFIG_LOG_TAG_DEFAULT) <= CONFIG_LOG_TAG_MAX_LEN + 1,
"Default string longer than tag capacity")));
static char tag[CONFIG_LOG_TAG_MAX_LEN + 1] =
COND_CODE_0(CONFIG_LOG_TAG_MAX_LEN, ({}), (CONFIG_LOG_TAG_DEFAULT));
bool log_is_strdup(const void *buf);
static void msg_process(union log_msgs msg, bool bypass);
static log_timestamp_t dummy_timestamp(void)
{
return 0;
}
uint32_t z_log_get_s_mask(const char *str, uint32_t nargs)
{
char curr;
bool arm = false;
uint32_t arg = 0U;
uint32_t mask = 0U;
__ASSERT_NO_MSG(nargs <= 8*sizeof(mask));
while ((curr = *str++) && arg < nargs) {
if (curr == '%') {
arm = !arm;
} else if (arm && isalpha((int)curr)) {
if (curr == 's') {
mask |= BIT(arg);
}
arm = false;
arg++;
} else {
; /* standard character, continue walk */
}
}
return mask;
}
/**
* @brief Check if address is in read only section.
*
* @param addr Address.
*
* @return True if address identified within read only section.
*/
static bool is_rodata(const void *addr)
{
#if defined(CONFIG_ARM) || defined(CONFIG_ARC) || defined(CONFIG_X86) || \
defined(CONFIG_ARM64) || defined(CONFIG_NIOS2) || \
defined(CONFIG_RISCV) || defined(CONFIG_SPARC)
extern const char *__rodata_region_start[];
extern const char *__rodata_region_end[];
#define RO_START __rodata_region_start
#define RO_END __rodata_region_end
#elif defined(CONFIG_XTENSA)
extern const char *_rodata_start[];
extern const char *_rodata_end[];
#define RO_START _rodata_start
#define RO_END _rodata_end
#else
#define RO_START 0
#define RO_END 0
#endif
return (((const char *)addr >= (const char *)RO_START) &&
((const char *)addr < (const char *)RO_END));
}
/**
* @brief Scan string arguments and report every address which is not in read
* only memory and not yet duplicated.
*
* @param msg Log message.
*/
static void detect_missed_strdup(struct log_msg *msg)
{
#define ERR_MSG "argument %d in source %s log message \"%s\" missing " \
"log_strdup()."
uint32_t idx;
const char *str;
const char *msg_str;
uint32_t mask;
if (!log_msg_is_std(msg)) {
return;
}
msg_str = log_msg_str_get(msg);
mask = z_log_get_s_mask(msg_str, log_msg_nargs_get(msg));
while (mask) {
idx = 31 - __builtin_clz(mask);
str = (const char *)log_msg_arg_get(msg, idx);
if (!is_rodata(str) && !log_is_strdup(str) &&
(str != log_strdup_fail_msg)) {
const char *src_name =
log_source_name_get(CONFIG_LOG_DOMAIN_ID,
log_msg_source_id_get(msg));
if (IS_ENABLED(CONFIG_ASSERT)) {
__ASSERT(0, ERR_MSG, idx, src_name, msg_str);
} else {
LOG_ERR(ERR_MSG, idx, src_name, msg_str);
}
}
mask &= ~BIT(idx);
}
#undef ERR_MSG
}
static void z_log_msg_post_finalize(void)
{
atomic_inc(&buffered_cnt);
if (panic_mode) {
unsigned int key = irq_lock();
(void)log_process(false);
irq_unlock(key);
} else if (proc_tid != NULL && buffered_cnt == 1) {
k_timer_start(&log_process_thread_timer,
K_MSEC(CONFIG_LOG_PROCESS_THREAD_SLEEP_MS), K_NO_WAIT);
} else if (CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
if ((buffered_cnt == CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) &&
(proc_tid != NULL)) {
k_timer_stop(&log_process_thread_timer);
k_sem_give(&log_process_thread_sem);
}
} else {
/* No action needed. Message processing will be triggered by the
* timeout or when number of upcoming messages exceeds the
* threshold.
*/
;
}
}
static inline void msg_finalize(struct log_msg *msg,
struct log_msg_ids src_level)
{
unsigned int key;
msg->hdr.ids = src_level;
msg->hdr.timestamp = timestamp_func();
key = irq_lock();
log_list_add_tail(&list, msg);
irq_unlock(key);
z_log_msg_post_finalize();
}
void log_0(const char *str, struct log_msg_ids src_level)
{
if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
log_frontend_0(str, src_level);
} else {
struct log_msg *msg = log_msg_create_0(str);
if (msg == NULL) {
return;
}
msg_finalize(msg, src_level);
}
}
void log_1(const char *str,
log_arg_t arg0,
struct log_msg_ids src_level)
{
if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
log_frontend_1(str, arg0, src_level);
} else {
struct log_msg *msg = log_msg_create_1(str, arg0);
if (msg == NULL) {
return;
}
msg_finalize(msg, src_level);
}
}
void log_2(const char *str,
log_arg_t arg0,
log_arg_t arg1,
struct log_msg_ids src_level)
{
if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
log_frontend_2(str, arg0, arg1, src_level);
} else {
struct log_msg *msg = log_msg_create_2(str, arg0, arg1);
if (msg == NULL) {
return;
}
msg_finalize(msg, src_level);
}
}
void log_3(const char *str,
log_arg_t arg0,
log_arg_t arg1,
log_arg_t arg2,
struct log_msg_ids src_level)
{
if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
log_frontend_3(str, arg0, arg1, arg2, src_level);
} else {
struct log_msg *msg = log_msg_create_3(str, arg0, arg1, arg2);
if (msg == NULL) {
return;
}
msg_finalize(msg, src_level);
}
}
void log_n(const char *str,
log_arg_t *args,
uint32_t narg,
struct log_msg_ids src_level)
{
if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
log_frontend_n(str, args, narg, src_level);
} else {
struct log_msg *msg = log_msg_create_n(str, args, narg);
if (msg == NULL) {
return;
}
msg_finalize(msg, src_level);
}
}
void log_hexdump(const char *str, const void *data, uint32_t length,
struct log_msg_ids src_level)
{
if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
log_frontend_hexdump(str, (const uint8_t *)data, length,
src_level);
} else {
struct log_msg *msg =
log_msg_hexdump_create(str, (const uint8_t *)data, length);
if (msg == NULL) {
return;
}
msg_finalize(msg, src_level);
}
}
void z_log_printk(const char *fmt, va_list ap)
{
if (IS_ENABLED(CONFIG_LOG_PRINTK)) {
union {
struct log_msg_ids structure;
uint32_t value;
} src_level_union = {
{
.level = LOG_LEVEL_INTERNAL_RAW_STRING
}
};
if (k_is_user_context()) {
uint8_t str[CONFIG_LOG_PRINTK_MAX_STRING_LENGTH + 1];
vsnprintk(str, sizeof(str), fmt, ap);
z_log_string_from_user(src_level_union.value, str);
} else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
log_generic(src_level_union.structure, fmt, ap,
LOG_STRDUP_SKIP);
} else {
uint8_t str[CONFIG_LOG_PRINTK_MAX_STRING_LENGTH + 1];
struct log_msg *msg;
int length;
length = vsnprintk(str, sizeof(str), fmt, ap);
length = MIN(length, sizeof(str));
msg = log_msg_hexdump_create(NULL, str, length);
if (msg == NULL) {
return;
}
msg_finalize(msg, src_level_union.structure);
}
}
}
/** @brief Count number of arguments in formatted string.
*
* Function counts number of '%' not followed by '%'.
*/
uint32_t log_count_args(const char *fmt)
{
uint32_t args = 0U;
bool prev = false; /* if previous char was a modificator. */
while (*fmt != '\0') {
if (*fmt == '%') {
prev = !prev;
} else if (prev) {
args++;
prev = false;
} else {
; /* standard character, continue walk */
}
fmt++;
}
return args;
}
void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap,
enum log_strdup_action strdup_action)
{
if (k_is_user_context()) {
log_generic_from_user(src_level, fmt, ap);
} else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) &&
(!IS_ENABLED(CONFIG_LOG_FRONTEND))) {
struct log_backend const *backend;
uint32_t timestamp = timestamp_func();
for (int i = 0; i < log_backend_count_get(); i++) {
backend = log_backend_get(i);
bool runtime_ok =
IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ?
(src_level.level <= log_filter_get(backend,
src_level.domain_id,
src_level.source_id,
true)) : true;
if (log_backend_is_active(backend) && runtime_ok) {
va_list ap_tmp;
va_copy(ap_tmp, ap);
log_backend_put_sync_string(backend, src_level,
timestamp, fmt, ap_tmp);
va_end(ap_tmp);
}
}
} else {
log_arg_t args[LOG_MAX_NARGS];
uint32_t nargs = log_count_args(fmt);
__ASSERT_NO_MSG(nargs < LOG_MAX_NARGS);
for (int i = 0; i < nargs; i++) {
args[i] = va_arg(ap, log_arg_t);
}
if (strdup_action != LOG_STRDUP_SKIP) {
uint32_t mask = z_log_get_s_mask(fmt, nargs);
while (mask) {
uint32_t idx = 31 - __builtin_clz(mask);
const char *str = (const char *)args[idx];
/* is_rodata(str) is not checked,
* because log_strdup does it.
* Hence, we will do only optional check
* if already not duplicated.
*/
if (strdup_action == LOG_STRDUP_EXEC
|| !log_is_strdup(str)) {
args[idx] = (log_arg_t)log_strdup(str);
}
mask &= ~BIT(idx);
}
}
log_n(fmt, args, nargs, src_level);
}
}
void log_string_sync(struct log_msg_ids src_level, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
log_generic(src_level, fmt, ap, LOG_STRDUP_SKIP);
va_end(ap);
}
void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata,
const void *data, uint32_t len)
{
if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
log_frontend_hexdump(metadata, (const uint8_t *)data, len,
src_level);
} else {
struct log_backend const *backend;
log_timestamp_t timestamp = timestamp_func();
for (int i = 0; i < log_backend_count_get(); i++) {
backend = log_backend_get(i);
bool runtime_ok =
IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ?
(src_level.level <= log_filter_get(backend,
src_level.domain_id,
src_level.source_id,
true)) : true;
if (log_backend_is_active(backend) && runtime_ok) {
log_backend_put_sync_hexdump(
backend, src_level, timestamp, metadata,
(const uint8_t *)data, len);
}
}
}
}
static log_timestamp_t default_get_timestamp(void)
{
return IS_ENABLED(CONFIG_LOG_TIMESTAMP_64BIT) ?
sys_clock_tick_get() : k_cycle_get_32();
}
static log_timestamp_t default_lf_get_timestamp(void)
{
return IS_ENABLED(CONFIG_LOG_TIMESTAMP_64BIT) ?
k_uptime_get() : k_uptime_get_32();
}
void log_core_init(void)
{
uint32_t freq;
log_timestamp_get_t _timestamp_func;
panic_mode = false;
dropped_cnt = 0;
/* Set default timestamp. */
if (sys_clock_hw_cycles_per_sec() > 1000000) {
_timestamp_func = default_lf_get_timestamp;
freq = 1000U;
} else {
_timestamp_func = default_get_timestamp;
freq = sys_clock_hw_cycles_per_sec();
}
log_set_timestamp_func(_timestamp_func, freq);
if (IS_ENABLED(CONFIG_LOG2)) {
if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) {
z_log_msg2_init();
}
} else if (IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
log_msg_pool_init();
log_list_init(&list);
k_mem_slab_init(&log_strdup_pool, log_strdup_pool_buf,
sizeof(struct log_strdup_buf),
CONFIG_LOG_STRDUP_BUF_COUNT);
}
if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
z_log_runtime_filters_init();
}
}
void log_init(void)
{
__ASSERT_NO_MSG(log_backend_count_get() < LOG_FILTERS_NUM_OF_SLOTS);
int i;
if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
log_frontend_init();
}
if (atomic_inc(&initialized) != 0) {
return;
}
/* Assign ids to backends. */
for (i = 0; i < log_backend_count_get(); i++) {
const struct log_backend *backend = log_backend_get(i);
if (backend->autostart) {
if (backend->api->init != NULL) {
backend->api->init(backend);
}
log_backend_enable(backend,
backend->cb->ctx,
CONFIG_LOG_MAX_LEVEL);
}
}
}
static void thread_set(k_tid_t process_tid)
{
proc_tid = process_tid;
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
return;
}
if (CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD &&
process_tid &&
buffered_cnt >= CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
k_sem_give(&log_process_thread_sem);
}
}
void log_thread_set(k_tid_t process_tid)
{
if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
__ASSERT_NO_MSG(0);
} else {
thread_set(process_tid);
}
}
int log_set_timestamp_func(log_timestamp_get_t timestamp_getter, uint32_t freq)
{
if (timestamp_getter == NULL) {
return -EINVAL;
}
timestamp_func = timestamp_getter;
log_output_timestamp_freq_set(freq);
return 0;
}
void z_impl_log_panic(void)
{
struct log_backend const *backend;
if (panic_mode) {
return;
}
/* If panic happened early logger might not be initialized.
* Forcing initialization of the logger and auto-starting backends.
*/
log_init();
for (int i = 0; i < log_backend_count_get(); i++) {
backend = log_backend_get(i);
if (log_backend_is_active(backend)) {
log_backend_panic(backend);
}
}
if (!IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
/* Flush */
while (log_process(false) == true) {
}
}
panic_mode = true;
}
#ifdef CONFIG_USERSPACE
void z_vrfy_log_panic(void)
{
z_impl_log_panic();
}
#include <syscalls/log_panic_mrsh.c>
#endif
static bool msg_filter_check(struct log_backend const *backend,
union log_msgs msg)
{
if (IS_ENABLED(CONFIG_LOG2) && !z_log_item_is_msg(msg.msg2)) {
return true;
}
if (!IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
return true;
}
uint32_t backend_level;
uint8_t level;
uint8_t domain_id;
int16_t source_id;
if (IS_ENABLED(CONFIG_LOG2)) {
struct log_msg2 *msg2 = &msg.msg2->log;
struct log_source_dynamic_data *source =
(struct log_source_dynamic_data *)
log_msg2_get_source(msg2);
level = log_msg2_get_level(msg2);
domain_id = log_msg2_get_domain(msg2);
source_id = source ? log_dynamic_source_id(source) : -1;
} else {
level = log_msg_level_get(msg.msg);
domain_id = log_msg_domain_id_get(msg.msg);
source_id = log_msg_source_id_get(msg.msg);
}
backend_level = log_filter_get(backend, domain_id,
source_id, true);
return (level <= backend_level);
}
static void msg_process(union log_msgs msg, bool bypass)
{
struct log_backend const *backend;
if (!bypass) {
if (!IS_ENABLED(CONFIG_LOG2) &&
IS_ENABLED(CONFIG_LOG_DETECT_MISSED_STRDUP) &&
!panic_mode) {
detect_missed_strdup(msg.msg);
}
for (int i = 0; i < log_backend_count_get(); i++) {
backend = log_backend_get(i);
if (log_backend_is_active(backend) &&
msg_filter_check(backend, msg)) {
if (IS_ENABLED(CONFIG_LOG2)) {
log_backend_msg2_process(backend,
msg.msg2);
} else {
log_backend_put(backend, msg.msg);
}
}
}
}
if (!IS_ENABLED(CONFIG_LOG2_MODE_IMMEDIATE)) {
if (IS_ENABLED(CONFIG_LOG2)) {
z_log_msg2_free(msg.msg2);
} else {
log_msg_put(msg.msg);
}
}
}
void dropped_notify(void)
{
uint32_t dropped = z_log_dropped_read_and_clear();
for (int i = 0; i < log_backend_count_get(); i++) {
struct log_backend const *backend = log_backend_get(i);
if (log_backend_is_active(backend)) {
log_backend_dropped(backend, dropped);
}
}
}
union log_msgs get_msg(void)
{
union log_msgs msg;
if (IS_ENABLED(CONFIG_LOG2)) {
msg.msg2 = z_log_msg2_claim();
return msg;
}
int key = irq_lock();
msg.msg = log_list_head_get(&list);
irq_unlock(key);
return msg;
}
static bool next_pending(void)
{
if (IS_ENABLED(CONFIG_LOG2)) {
return z_log_msg2_pending();
}
return (log_list_head_peek(&list) != NULL);
}
void z_log_notify_backend_enabled(void)
{
/* Wakeup logger thread after attaching first backend. It might be
* blocked with log messages pending.
*/
if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD) && !backend_attached) {
k_sem_give(&log_process_thread_sem);
}
backend_attached = true;
}
bool z_impl_log_process(bool bypass)
{
union log_msgs msg;
if (!backend_attached && !bypass) {
return false;
}
msg = get_msg();
if (msg.msg) {
atomic_dec(&buffered_cnt);
msg_process(msg, bypass);
}
if (!bypass && z_log_dropped_pending()) {
dropped_notify();
}
return next_pending();
}
#ifdef CONFIG_USERSPACE
bool z_vrfy_log_process(bool bypass)
{
return z_impl_log_process(bypass);
}
#include <syscalls/log_process_mrsh.c>
#endif
uint32_t z_impl_log_buffered_cnt(void)
{
return buffered_cnt;
}
#ifdef CONFIG_USERSPACE
uint32_t z_vrfy_log_buffered_cnt(void)
{
return z_impl_log_buffered_cnt();
}
#include <syscalls/log_buffered_cnt_mrsh.c>
#endif
void z_log_dropped(void)
{
atomic_inc(&dropped_cnt);
atomic_dec(&buffered_cnt);
}
uint32_t z_log_dropped_read_and_clear(void)
{
return atomic_set(&dropped_cnt, 0);
}
bool z_log_dropped_pending(void)
{
return dropped_cnt > 0;
}
static void notify_drop(const struct mpsc_pbuf_buffer *buffer,
const union mpsc_pbuf_generic *item)
{
ARG_UNUSED(buffer);
ARG_UNUSED(item);
z_log_dropped();
}
char *z_log_strdup(const char *str)
{
struct log_strdup_buf *dup;
int err;
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) ||
is_rodata(str) || k_is_user_context()) {
return (char *)str;
}
err = k_mem_slab_alloc(&log_strdup_pool, (void **)&dup, K_NO_WAIT);
if (err != 0) {
/* failed to allocate */
return (char *)log_strdup_fail_msg;
}
if (IS_ENABLED(CONFIG_LOG_STRDUP_POOL_PROFILING)) {
size_t slen = strlen(str);
static struct k_spinlock lock;
k_spinlock_key_t key;
key = k_spin_lock(&lock);
log_strdup_in_use++;
log_strdup_max = MAX(log_strdup_in_use, log_strdup_max);
log_strdup_longest = MAX(slen, log_strdup_longest);
k_spin_unlock(&lock, key);
}
/* Set 'allocated' flag. */
(void)atomic_set(&dup->refcount, 1);
strncpy(dup->buf, str, sizeof(dup->buf) - 2);
dup->buf[sizeof(dup->buf) - 2] = '~';
dup->buf[sizeof(dup->buf) - 1] = '\0';
return dup->buf;
}
uint32_t log_get_strdup_pool_current_utilization(void)
{
return IS_ENABLED(CONFIG_LOG_STRDUP_POOL_PROFILING) ?
log_strdup_in_use : 0;
}
uint32_t log_get_strdup_pool_utilization(void)
{
return IS_ENABLED(CONFIG_LOG_STRDUP_POOL_PROFILING) ?
log_strdup_max : 0;
}
uint32_t log_get_strdup_longest_string(void)
{
return IS_ENABLED(CONFIG_LOG_STRDUP_POOL_PROFILING) ?
log_strdup_longest : 0;
}
bool log_is_strdup(const void *buf)
{
return PART_OF_ARRAY(log_strdup_pool_buf, (uint8_t *)buf);
}
void z_log_free(void *str)
{
struct log_strdup_buf *dup = CONTAINER_OF(str, struct log_strdup_buf,
buf);
if (atomic_dec(&dup->refcount) == 1) {
k_mem_slab_free(&log_strdup_pool, (void **)&dup);
if (IS_ENABLED(CONFIG_LOG_STRDUP_POOL_PROFILING)) {
atomic_dec(&log_strdup_in_use);
}
}
}
#if defined(CONFIG_USERSPACE)
/* LCOV_EXCL_START */
void z_impl_z_log_string_from_user(uint32_t src_level_val, const char *str)
{
ARG_UNUSED(src_level_val);
ARG_UNUSED(str);
__ASSERT(false, "This function can be called from user mode only.");
}
/* LCOV_EXCL_STOP */
void z_vrfy_z_log_string_from_user(uint32_t src_level_val, const char *str)
{
uint8_t level, domain_id, source_id;
union {
struct log_msg_ids structure;
uint32_t value;
} src_level_union;
size_t len;
int err;
src_level_union.value = src_level_val;
level = src_level_union.structure.level;
domain_id = src_level_union.structure.domain_id;
source_id = src_level_union.structure.source_id;
Z_OOPS(Z_SYSCALL_VERIFY_MSG(
(IS_ENABLED(CONFIG_LOG_PRINTK) || (level >= LOG_LEVEL_ERR)) &&
(level <= LOG_LEVEL_DBG),
"Invalid log level"));
Z_OOPS(Z_SYSCALL_VERIFY_MSG(domain_id == CONFIG_LOG_DOMAIN_ID,
"Invalid log domain_id"));
Z_OOPS(Z_SYSCALL_VERIFY_MSG(source_id < z_log_sources_count(),
"Invalid log source id"));
if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) &&
(level != LOG_LEVEL_INTERNAL_RAW_STRING) &&
(level > LOG_FILTER_SLOT_GET(z_log_dynamic_filters_get(source_id),
LOG_FILTER_AGGR_SLOT_IDX))) {
/* Skip filtered out messages. */
return;
}
/*
* Validate and make a copy of the source string. Because we need
* the log subsystem to eventually free it, we're going to use
* log_strdup().
*/
len = z_user_string_nlen(str, (level == LOG_LEVEL_INTERNAL_RAW_STRING) ?
CONFIG_LOG_PRINTK_MAX_STRING_LENGTH :
CONFIG_LOG_STRDUP_MAX_STRING, &err);
Z_OOPS(Z_SYSCALL_VERIFY_MSG(err == 0, "invalid string passed in"));
Z_OOPS(Z_SYSCALL_MEMORY_READ(str, len));
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
log_string_sync(src_level_union.structure, "%s", str);
} else if (IS_ENABLED(CONFIG_LOG_PRINTK) &&
(level == LOG_LEVEL_INTERNAL_RAW_STRING)) {
struct log_msg *msg;
msg = log_msg_hexdump_create(NULL, str, len);
if (msg != NULL) {
msg_finalize(msg, src_level_union.structure);
}
} else {
str = log_strdup(str);
log_1("%s", (log_arg_t)str, src_level_union.structure);
}
}
#include <syscalls/z_log_string_from_user_mrsh.c>
void log_generic_from_user(struct log_msg_ids src_level,
const char *fmt, va_list ap)
{
char buffer[CONFIG_LOG_STRDUP_MAX_STRING + 1];
union {
struct log_msg_ids structure;
uint32_t value;
} src_level_union;
vsnprintk(buffer, sizeof(buffer), fmt, ap);
__ASSERT_NO_MSG(sizeof(src_level) <= sizeof(uint32_t));
src_level_union.structure = src_level;
z_log_string_from_user(src_level_union.value, buffer);
}
void log_from_user(struct log_msg_ids src_level, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
log_generic_from_user(src_level, fmt, ap);
va_end(ap);
}
/* LCOV_EXCL_START */
void z_impl_z_log_hexdump_from_user(uint32_t src_level_val, const char *metadata,
const uint8_t *data, uint32_t len)
{
ARG_UNUSED(src_level_val);
ARG_UNUSED(metadata);
ARG_UNUSED(data);
ARG_UNUSED(len);
__ASSERT(false, "This function can be called from user mode only.");
}
/* LCOV_EXCL_STOP */
void z_vrfy_z_log_hexdump_from_user(uint32_t src_level_val, const char *metadata,
const uint8_t *data, uint32_t len)
{
union {
struct log_msg_ids structure;
uint32_t value;
} src_level_union;
int err;
char kmeta[CONFIG_LOG_STRDUP_MAX_STRING];
src_level_union.value = src_level_val;
Z_OOPS(Z_SYSCALL_VERIFY_MSG(
(src_level_union.structure.level <= LOG_LEVEL_DBG) &&
(src_level_union.structure.level >= LOG_LEVEL_ERR),
"Invalid log level"));
Z_OOPS(Z_SYSCALL_VERIFY_MSG(
src_level_union.structure.domain_id == CONFIG_LOG_DOMAIN_ID,
"Invalid log domain_id"));
Z_OOPS(Z_SYSCALL_VERIFY_MSG(
src_level_union.structure.source_id < z_log_sources_count(),
"Invalid log source id"));
if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) &&
(src_level_union.structure.level > LOG_FILTER_SLOT_GET(
z_log_dynamic_filters_get(src_level_union.structure.source_id),
LOG_FILTER_AGGR_SLOT_IDX))) {
/* Skip filtered out messages. */
return;
}
/*
* Validate and make a copy of the metadata string. Because we
* need the log subsystem to eventually free it, we're going
* to use log_strdup().
*/
err = z_user_string_copy(kmeta, metadata, sizeof(kmeta));
Z_OOPS(Z_SYSCALL_VERIFY_MSG(err == 0, "invalid meta passed in"));
Z_OOPS(Z_SYSCALL_MEMORY_READ(data, len));
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
log_hexdump_sync(src_level_union.structure,
kmeta, data, len);
} else {
metadata = log_strdup(kmeta);
log_hexdump(metadata, data, len, src_level_union.structure);
}
}
#include <syscalls/z_log_hexdump_from_user_mrsh.c>
void log_hexdump_from_user(struct log_msg_ids src_level, const char *metadata,
const void *data, uint32_t len)
{
union {
struct log_msg_ids structure;
uint32_t value;
} src_level_union;
__ASSERT_NO_MSG(sizeof(src_level) <= sizeof(uint32_t));
src_level_union.structure = src_level;
z_log_hexdump_from_user(src_level_union.value, metadata,
(const uint8_t *)data, len);
}
#else
/* LCOV_EXCL_START */
void z_impl_z_log_string_from_user(uint32_t src_level_val, const char *str)
{
ARG_UNUSED(src_level_val);
ARG_UNUSED(str);
__ASSERT_NO_MSG(false);
}
void z_vrfy_z_log_hexdump_from_user(uint32_t src_level_val, const char *metadata,
const uint8_t *data, uint32_t len)
{
ARG_UNUSED(src_level_val);
ARG_UNUSED(metadata);
ARG_UNUSED(data);
ARG_UNUSED(len);
__ASSERT_NO_MSG(false);
}
void log_from_user(struct log_msg_ids src_level, const char *fmt, ...)
{
ARG_UNUSED(src_level);
ARG_UNUSED(fmt);
__ASSERT_NO_MSG(false);
}
void log_generic_from_user(struct log_msg_ids src_level,
const char *fmt, va_list ap)
{
ARG_UNUSED(src_level);
ARG_UNUSED(fmt);
ARG_UNUSED(ap);
__ASSERT_NO_MSG(false);
}
void log_hexdump_from_user(struct log_msg_ids src_level, const char *metadata,
const void *data, uint32_t len)
{
ARG_UNUSED(src_level);
ARG_UNUSED(metadata);
ARG_UNUSED(data);
ARG_UNUSED(len);
__ASSERT_NO_MSG(false);
}
/* LCOV_EXCL_STOP */
#endif /* !defined(CONFIG_USERSPACE) */
void z_log_msg2_init(void)
{
mpsc_pbuf_init(&log_buffer, &mpsc_config);
}
struct log_msg2 *z_log_msg2_alloc(uint32_t wlen)
{
return (struct log_msg2 *)mpsc_pbuf_alloc(&log_buffer, wlen,
K_MSEC(CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS));
}
void z_log_msg2_commit(struct log_msg2 *msg)
{
msg->hdr.timestamp = timestamp_func();
if (IS_ENABLED(CONFIG_LOG2_MODE_IMMEDIATE)) {
union log_msgs msgs = {
.msg2 = (union log_msg2_generic *)msg
};
msg_process(msgs, false);
return;
}
mpsc_pbuf_commit(&log_buffer, (union mpsc_pbuf_generic *)msg);
if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) {
z_log_msg_post_finalize();
}
}
union log_msg2_generic *z_log_msg2_claim(void)
{
return (union log_msg2_generic *)mpsc_pbuf_claim(&log_buffer);
}
void z_log_msg2_free(union log_msg2_generic *msg)
{
mpsc_pbuf_free(&log_buffer, (union mpsc_pbuf_generic *)msg);
}
bool z_log_msg2_pending(void)
{
return mpsc_pbuf_is_pending(&log_buffer);
}
const char *z_log_get_tag(void)
{
return CONFIG_LOG_TAG_MAX_LEN > 0 ? tag : NULL;
}
int log_set_tag(const char *str)
{
if (CONFIG_LOG_TAG_MAX_LEN == 0) {
return -ENOTSUP;
}
if (str == NULL) {
return -EINVAL;
}
size_t len = strlen(str);
size_t cpy_len = MIN(len, CONFIG_LOG_TAG_MAX_LEN);
memcpy(tag, str, cpy_len);
tag[cpy_len] = '\0';
if (cpy_len < len) {
tag[cpy_len - 1] = '~';
return -ENOMEM;
}
return 0;
}
static void log_process_thread_timer_expiry_fn(struct k_timer *timer)
{
k_sem_give(&log_process_thread_sem);
}
static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
{
__ASSERT_NO_MSG(log_backend_count_get() > 0);
log_init();
thread_set(k_current_get());
while (true) {
if (log_process(false) == false) {
k_sem_take(&log_process_thread_sem, K_FOREVER);
}
}
}
K_KERNEL_STACK_DEFINE(logging_stack, CONFIG_LOG_PROCESS_THREAD_STACK_SIZE);
struct k_thread logging_thread;
static int enable_logger(const struct device *arg)
{
ARG_UNUSED(arg);
if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
k_timer_init(&log_process_thread_timer,
log_process_thread_timer_expiry_fn, NULL);
/* start logging thread */
k_thread_create(&logging_thread, logging_stack,
K_KERNEL_STACK_SIZEOF(logging_stack),
log_process_thread_func, NULL, NULL, NULL,
K_LOWEST_APPLICATION_THREAD_PRIO, 0,
COND_CODE_1(CONFIG_LOG_PROCESS_THREAD,
K_MSEC(CONFIG_LOG_PROCESS_THREAD_STARTUP_DELAY_MS),
K_NO_WAIT));
k_thread_name_set(&logging_thread, "logging");
} else {
log_init();
}
return 0;
}
SYS_INIT(enable_logger, POST_KERNEL, 0);
View git blame Copy permalink