subsys/logging/log_core.c

/*
 * 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>
#include <logging/log_output_dict.h>
#include <linker/utils.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

#ifndef CONFIG_LOG_TAG_MAX_LEN
#define CONFIG_LOG_TAG_MAX_LEN 0
#endif

#ifndef CONFIG_LOG2_ALWAYS_RUNTIME
BUILD_ASSERT(!IS_ENABLED(CONFIG_NO_OPTIMIZATIONS),
	     "Option must be enabled when CONFIG_NO_OPTIMIZATIONS is set");
BUILD_ASSERT(!IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE),
	     "Option must be enabled when CONFIG_LOG_MODE_IMMEDIATE is set");
#endif

#ifndef CONFIG_LOG1
static const log_format_func_t format_table[] = {
	[LOG_OUTPUT_TEXT] = log_output_msg2_process,
	[LOG_OUTPUT_SYST] = IS_ENABLED(CONFIG_LOG_MIPI_SYST_ENABLE) ?
						log_output_msg2_syst_process : NULL,
	[LOG_OUTPUT_DICT] = IS_ENABLED(CONFIG_LOG_DICTIONARY_SUPPORT) ?
						log_dict_output_msg2_process : NULL
};

log_format_func_t log_format_func_t_get(uint32_t log_type)
{
	return format_table[log_type];
}

size_t log_format_table_size(void)
{
	return ARRAY_SIZE(format_table);
}
#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) |
		 (IS_ENABLED(CONFIG_LOG_MEM_UTILIZATION) ?
		  MPSC_PBUF_MAX_UTILIZATION : 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 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 (!linker_is_in_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_val_t cnt = atomic_inc(&buffered_cnt);

	if (panic_mode) {
		unsigned int key = irq_lock();
		(void)log_process(false);
		irq_unlock(key);
	} else if (proc_tid != NULL && cnt == 0) {
		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 ((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);
	}
}

#ifndef CONFIG_LOG1
const struct log_backend *log_format_set_all_active_backends(size_t log_type)
{
	const struct log_backend *backend;
	const struct log_backend *failed_backend = NULL;

	for (int i = 0; i < log_backend_count_get(); i++) {
		backend = log_backend_get(i);
		if (log_backend_is_active(backend)) {
			int retCode = log_backend_format_set(backend, log_type);

			if (retCode != 0) {
				failed_backend = backend;
			}
		}
	}
	return failed_backend;
}
#endif

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_vprintk(const char *fmt, va_list ap)
{
	if (!IS_ENABLED(CONFIG_LOG_PRINTK)) {
		return;
	}

	if (!IS_ENABLED(CONFIG_LOG1)) {
		z_log_msg2_runtime_vcreate(CONFIG_LOG_DOMAIN_ID, NULL,
					   LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0, 0,
					   fmt, ap);
		return;
	}

	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_MODE_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_MODE_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];

				/* linker_is_in_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_DEFERRED)) {
		z_log_msg2_init();
	} else if (IS_ENABLED(CONFIG_LOG1_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_MODE_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();

	if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
		log_frontend_panic();
	}

	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_MODE_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_DEFERRED)) {
		z_log_msg2_free(msg.msg2);
	} else if (IS_ENABLED(CONFIG_LOG1_DEFERRED)) {
		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) {
		if (!bypass) {
			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(bool buffered)
{
	atomic_inc(&dropped_cnt);
	if (buffered) {
		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(true);
}


char *z_log_strdup(const char *str)
{
	struct log_strdup_buf *dup;
	int err;

	if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ||
	    linker_is_in_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_LOG1_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_LOG1_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_LOG_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);
	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;
}

int log_mem_get_usage(uint32_t *buf_size, uint32_t *usage)
{
	__ASSERT_NO_MSG(buf_size != NULL);
	__ASSERT_NO_MSG(usage != NULL);

	if (!IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
		return -EINVAL;
	}

	if (IS_ENABLED(CONFIG_LOG1)) {
		*buf_size = CONFIG_LOG_BUFFER_SIZE;
		*usage = log_msg_mem_get_used() * log_msg_get_slab_size();
		return 0;
	}

	mpsc_pbuf_get_utilization(&log_buffer, buf_size, usage);

	return 0;
}

int log_mem_get_max_usage(uint32_t *max)
{
	__ASSERT_NO_MSG(max != NULL);

	if (!IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
		return -EINVAL;
	}

	if (IS_ENABLED(CONFIG_LOG1)) {
		*max = log_msg_mem_get_max_used() * log_msg_get_slab_size();
		return 0;
	}

	return mpsc_pbuf_get_max_utilization(&log_buffer, max);
}

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);