michaelh/zephyr
1
0
Fork 0
Code Releases Activity

logging: Add basic userspace support

Browse source 
This commit adds basic userspace support to the logging subsystem.
With this change, the following API could be called from user mode:
- LOG_*()
- LOG_INST_*(),
- LOG_HEXDUMP_*(),
- LOG_HEXDUMP_INST_*(),
- LOG_PANIC(), LOG_PROCESS(),
- log_printk(), log_generic(), log_buffrered_cnt(),
- log_filter_set(NULL, ...)

With userspace disabled, the logger behavior and performance
is not affected. With userspace enabled, the calls from kernel
space have an additional overhead introduced by _is_user_context().

The logger behavior changes when it is called from the user context.
All strings logged using LOG_*() and LOG_INST_*() API from userspace
are rendered in place for security reasons and then placed in
log_strdup() memory pool, which should be large enough to hold bursts
of log messages.

Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>
Signed-off-by: Piotr Zięcik <piotr.ziecik@nordicsemi.no>
This commit is contained in:
Piotr Zięcik 2019-08-22 11:13:22 +02:00 • committed by Anas Nashif
commit 892ab4e356
7 changed files with 399 additions and 43 deletions
Download patch file Download diff file Expand all files Collapse all files

74
include/logging/log_core.h
View file

@ -8,10 +8,11 @@
#include <logging/log_msg.h>
#include <logging/log_instance.h>
#include <sys/util.h>
#include <stdbool.h>
#include <stdint.h>
#include <stdarg.h>
#include <syscall.h>
#include <sys/util.h>
#ifdef __cplusplus
extern "C" {
@ -162,9 +163,11 @@ extern "C" {
#define Z_LOG_INTERNAL_X(N, ...) UTIL_CAT(_LOG_INTERNAL_, N)(__VA_ARGS__)
#define __LOG_INTERNAL(_src_level, ...) \
#define __LOG_INTERNAL(is_user_context, _src_level, ...) \
do { \
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \
if (is_user_context) { \
log_from_user(_src_level, __VA_ARGS__); \
} else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \
log_string_sync(_src_level, __VA_ARGS__); \
} else { \
Z_LOG_INTERNAL_X(Z_LOG_NARGS_POSTFIX(__VA_ARGS__), \
@ -212,8 +215,11 @@ extern "C" {
/******************************************************************************/
#define __LOG(_level, _id, _filter, ...) \
do { \
bool is_user_context = _is_user_context(); \
\
if (Z_LOG_CONST_LEVEL_CHECK(_level) && \
(_level <= LOG_RUNTIME_FILTER(_filter))) { \
(is_user_context || \
(_level <= LOG_RUNTIME_FILTER(_filter)))) { \
struct log_msg_ids src_level = { \
.level = _level, \
.domain_id = CONFIG_LOG_DOMAIN_ID, \
@ -221,10 +227,11 @@ extern "C" {
}; \
\
if ((BIT(_level) & LOG_FUNCTION_PREFIX_MASK) != 0U) {\
__LOG_INTERNAL(src_level, \
__LOG_INTERNAL(is_user_context, src_level, \
Z_LOG_STR(__VA_ARGS__)); \
} else { \
__LOG_INTERNAL(src_level, __VA_ARGS__); \
__LOG_INTERNAL(is_user_context, src_level, \
__VA_ARGS__); \
} \
} else if (false) { \
/* Arguments checker present but never evaluated.*/ \
@ -254,15 +261,21 @@ extern "C" {
/******************************************************************************/
#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length, _str) \
do { \
bool is_user_context = _is_user_context(); \
\
if (Z_LOG_CONST_LEVEL_CHECK(_level) && \
(_level <= LOG_RUNTIME_FILTER(_filter))) { \
(is_user_context || \
(_level <= LOG_RUNTIME_FILTER(_filter)))) { \
struct log_msg_ids src_level = { \
.level = _level, \
.source_id = _id, \
.domain_id = CONFIG_LOG_DOMAIN_ID \
}; \
\
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \
if (is_user_context) { \
log_hexdump_from_user(src_level, _str, \
_data, _length); \
} else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \
log_hexdump_sync(src_level, _str, \
_data, _length); \
} else { \
@ -526,6 +539,15 @@ void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata,
*/
void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap);
/**
* @brief Writes a generic log message to the log from user mode.
*
* @note This function is intended to be used internally
* by the logging subsystem.
*/
void log_generic_from_user(struct log_msg_ids src_level,
const char *fmt, va_list ap);
/** @brief Check if address belongs to the memory pool used for transient.
*
* @param buf Buffer.
@ -559,6 +581,42 @@ u32_t log_get_strdup_longest_string(void);
*/
void log_dropped(void);
/** @brief Log a message from user mode context.
*
* @note This function is intended to be used internally
* by the logging subsystem.
*
* @param src_level Log identification.
* @param fmt String to format.
* @param ... Variable list of arguments.
*/
void __printf_like(2, 3) log_from_user(struct log_msg_ids src_level,
const char *fmt, ...);
/* Internal function used by log_from_user(). */
__syscall void z_log_string_from_user(u32_t src_level_val, const char *str);
/** @brief Log binary data (displayed as hexdump) from user mode conext.
*
* @note This function is intended to be used internally
* by the logging subsystem.
*
* @param src_level Log identification.
* @param metadata Raw string associated with the data.
* @param data Data.
* @param len Data length.
*/
void log_hexdump_from_user(struct log_msg_ids src_level, const char *metadata,
const u8_t *data, u32_t len);
/* Internal function used by log_hexdump_from_user(). */
__syscall void z_log_hexdump_from_user(u32_t src_level_val,
const char *metadata,
const u8_t *data, u32_t len);
#include <syscalls/log_core.h>
#ifdef __cplusplus
}
#endif

10
include/logging/log_ctrl.h
View file

@ -75,7 +75,7 @@ int log_set_timestamp_func(timestamp_get_t timestamp_getter, u32_t freq);
* are flushed after switching to panic mode. In panic mode, all log
* messages must be processed in the context of the call.
*/
void log_panic(void);
__syscall void log_panic(void);
/**
* @brief Process one pending log message.
@ -85,14 +85,14 @@ void log_panic(void);
* @retval true There is more messages pending to be processed.
* @retval false No messages pending.
*/
bool log_process(bool bypass);
__syscall bool log_process(bool bypass);
/**
* @brief Return number of buffered log messages.
*
* @return Number of currently buffered log messages.
*/
u32_t log_buffered_cnt(void);
__syscall u32_t log_buffered_cnt(void);
/** @brief Get number of independent logger sources (modules and instances)
*
@ -144,7 +144,7 @@ u32_t log_filter_get(struct log_backend const *const backend,
* @return Actual level set which may be limited by compiled level. If filter
* was set for all backends then maximal level that was set is returned.
*/
u32_t log_filter_set(struct log_backend const *const backend,
__syscall u32_t log_filter_set(struct log_backend const *const backend,
u32_t domain_id,
u32_t src_id,
u32_t level);
@ -179,6 +179,8 @@ void log_backend_disable(struct log_backend const *const backend);
#define LOG_PROCESS() false
#endif
#include <syscalls/log_ctrl.h>
/**
* @}
*/

3
subsys/logging/Kconfig
View file

@ -6,6 +6,7 @@
menuconfig LOG
bool "Logging"
select PRINTK if USERSPACE
help
Global switch for the logger, when turned off log calls will not be
compiled in.
@ -94,7 +95,7 @@ config LOG_PRINTK
config LOG_PRINTK_MAX_STRING_LENGTH
int "Maximum string length supported by LOG_PRINTK"
depends on LOG_PRINTK
depends on !LOG_IMMEDIATE
depends on (!LOG_IMMEDIATE || USERSPACE)
default 128
help
Array is allocated on the stack.

317
subsys/logging/log_core.c
View file

@ -15,11 +15,12 @@
#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 1
#define CONFIG_LOG_PRINTK_MAX_STRING_LENGTH 0
#endif
#ifndef CONFIG_LOG_PROCESS_THREAD_SLEEP_MS
@ -324,27 +325,37 @@ int log_printk(const char *fmt, va_list ap)
int length = 0;
if (IS_ENABLED(CONFIG_LOG_PRINTK)) {
struct log_msg_ids src_level = {
union {
struct log_msg_ids structure;
u32_t value;
} src_level_union = {
{
.level = LOG_LEVEL_INTERNAL_RAW_STRING
}
};
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
log_generic(src_level, fmt, ap);
if (_is_user_context()) {
u8_t str[CONFIG_LOG_PRINTK_MAX_STRING_LENGTH + 1];
length = vsnprintk(str, sizeof(str), fmt, ap);
length = MIN(length, sizeof(str));
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);
} else {
u8_t formatted_str[CONFIG_LOG_PRINTK_MAX_STRING_LENGTH];
u8_t str[CONFIG_LOG_PRINTK_MAX_STRING_LENGTH + 1];
struct log_msg *msg;
length = vsnprintk(formatted_str,
sizeof(formatted_str), fmt, ap);
length = MIN(length, sizeof(formatted_str));
length = vsnprintk(str, sizeof(str), fmt, ap);
length = MIN(length, sizeof(str));
msg = log_msg_hexdump_create(NULL, formatted_str,
length);
msg = log_msg_hexdump_create(NULL, str, length);
if (msg == NULL) {
return 0;
}
msg_finalize(msg, src_level);
msg_finalize(msg, src_level_union.structure);
}
}
@ -375,7 +386,9 @@ static u32_t count_args(const char *fmt)
void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap)
{
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) &&
if (_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;
u32_t timestamp = timestamp_func();
@ -550,7 +563,7 @@ int log_set_timestamp_func(timestamp_get_t timestamp_getter, u32_t freq)
return 0;
}
void log_panic(void)
void z_impl_log_panic(void)
{
struct log_backend const *backend;
@ -580,6 +593,10 @@ void log_panic(void)
panic_mode = true;
}
#ifdef CONFIG_USERSPACE
Z_SYSCALL_HANDLER0_SIMPLE_VOID(log_panic);
#endif
static bool msg_filter_check(struct log_backend const *backend,
struct log_msg *msg)
{
@ -635,7 +652,7 @@ void dropped_notify(void)
}
}
bool log_process(bool bypass)
bool z_impl_log_process(bool bypass)
{
struct log_msg *msg;
@ -659,11 +676,22 @@ bool log_process(bool bypass)
return (log_list_head_peek(&list) != NULL);
}
u32_t log_buffered_cnt(void)
#ifdef CONFIG_USERSPACE
Z_SYSCALL_HANDLER(log_process, bypass)
{
return (u32_t)log_process((bool)(bypass));
}
#endif
u32_t z_impl_log_buffered_cnt(void)
{
return buffered_cnt;
}
#ifdef CONFIG_USERSPACE
Z_SYSCALL_HANDLER0_SIMPLE(log_buffered_cnt);
#endif
void log_dropped(void)
{
atomic_inc(&dropped_cnt);
@ -696,7 +724,7 @@ static u32_t max_filter_get(u32_t filters)
return max_filter;
}
u32_t log_filter_set(struct log_backend const *const backend,
u32_t z_impl_log_filter_set(struct log_backend const *const backend,
u32_t domain_id,
u32_t src_id,
u32_t level)
@ -745,16 +773,29 @@ u32_t log_filter_set(struct log_backend const *const backend,
return level;
}
#ifdef CONFIG_USERSPACE
Z_SYSCALL_HANDLER(log_filter_set, backend, domain_id, src_id, level)
{
Z_OOPS(Z_SYSCALL_VERIFY_MSG(backend == 0,
"Setting per-backend filters from user mode is not supported"));
Z_OOPS(Z_SYSCALL_VERIFY_MSG(domain_id == CONFIG_LOG_DOMAIN_ID,
"Invalid log domain_id"));
Z_OOPS(Z_SYSCALL_VERIFY_MSG(src_id < log_sources_count(),
"Invalid log source id"));
Z_OOPS(Z_SYSCALL_VERIFY_MSG(
(level <= LOG_LEVEL_DBG) && (level >= LOG_LEVEL_NONE),
"Invalid log level"));
return z_impl_log_filter_set(NULL, domain_id, src_id, level);
}
#endif
static void backend_filter_set(struct log_backend const *const backend,
u32_t level)
{
if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
for (int i = 0; i < log_sources_count(); i++) {
log_filter_set(backend,
CONFIG_LOG_DOMAIN_ID,
i,
level);
log_filter_set(backend, CONFIG_LOG_DOMAIN_ID, i, level);
}
}
}
@ -802,7 +843,8 @@ char *log_strdup(const char *str)
struct log_strdup_buf *dup;
int err;
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) || is_rodata(str)) {
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) ||
is_rodata(str) || _is_user_context()) {
return (char *)str;
}
@ -865,6 +907,237 @@ void log_free(void *str)
}
}
#if defined(CONFIG_USERSPACE)
void z_impl_z_log_string_from_user(u32_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.");
}
Z_SYSCALL_HANDLER(z_log_string_from_user, src_level_val, user_string_ptr)
{
const char *str = (const char *)(user_string_ptr);
u8_t level, domain_id, source_id;
union {
struct log_msg_ids structure;
u32_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 < 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(log_dynamic_filters_get(source_id),
LOG_FILTER_AGGR_SLOT_IDX))) {
/* Skip filtered out messages. */
return 0;
}
/*
* 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);
}
return 0;
}
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;
u32_t value;
} src_level_union;
vsnprintk(buffer, sizeof(buffer), fmt, ap);
__ASSERT_NO_MSG(sizeof(src_level) <= sizeof(u32_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);
}
void z_impl_z_log_hexdump_from_user(u32_t src_level_val, const char *metadata,
const u8_t *data, u32_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.");
}
Z_SYSCALL_HANDLER(z_log_hexdump_from_user, src_level_val,
user_metadata_ptr, user_data_ptr, len)
{
const char *metadata = (const char *)(user_metadata_ptr);
const void *data = (const void *)(user_data_ptr);
union {
struct log_msg_ids structure;
u32_t value;
} src_level_union;
size_t mlen;
int err;
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 < log_sources_count(),
"Invalid log source id"));
if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) &&
(src_level_union.structure.level > LOG_FILTER_SLOT_GET(
log_dynamic_filters_get(src_level_union.structure.source_id),
LOG_FILTER_AGGR_SLOT_IDX))) {
/* Skip filtered out messages. */
return 0;
}
/*
* 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().
*/
mlen = z_user_string_nlen(metadata, CONFIG_LOG_STRDUP_MAX_STRING, &err);
Z_OOPS(Z_SYSCALL_VERIFY_MSG(err == 0, "invalid string passed in"));
Z_OOPS(Z_SYSCALL_MEMORY_READ(metadata, mlen));
Z_OOPS(Z_SYSCALL_MEMORY_READ(data, len));
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
log_hexdump_sync(src_level_union.structure,
metadata, data, len);
} else {
metadata = log_strdup(metadata);
log_hexdump(metadata, data, len, src_level_union.structure);
}
return 0;
}
void log_hexdump_from_user(struct log_msg_ids src_level, const char *metadata,
const u8_t *data, u32_t len)
{
union {
struct log_msg_ids structure;
u32_t value;
} src_level_union;
__ASSERT_NO_MSG(sizeof(src_level) <= sizeof(u32_t));
src_level_union.structure = src_level;
z_log_hexdump_from_user(src_level_union.value, metadata, data, len);
}
#elif defined(CONFIG_NO_OPTIMIZATIONS)
/*
* With the optimizations disabled, the dead code is not removed and
* references to functions used only by the usermode remains in the
* object files, causing linker error. To avoid this error, here we
* are providing stubs for affected API.
*/
void z_impl_z_log_string_from_user(u32_t src_level_val, const char *str)
{
ARG_UNUSED(src_level_val);
ARG_UNUSED(str);
__ASSERT_NO_MSG(false);
}
void z_impl_z_log_hexdump_from_user(u32_t src_level_val, const char *metadata,
const u8_t *data, u32_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 u8_t *data, u32_t len)
{
ARG_UNUSED(src_level);
ARG_UNUSED(metadata);
ARG_UNUSED(data);
ARG_UNUSED(len);
__ASSERT_NO_MSG(false);
}
#endif /* defined(CONFIG_NO_OPTIMIZATIONS) */
static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
{
__ASSERT_NO_MSG(log_backend_count_get() > 0);

12
subsys/logging/log_msg.c
View file

@ -4,6 +4,7 @@
* SPDX-License-Identifier: Apache-2.0
*/
#include <kernel.h>
#include <logging/log.h>
#include <logging/log_msg.h>
#include <logging/log_ctrl.h>
#include <logging/log_core.h>
@ -85,6 +86,17 @@ static void msg_free(struct log_msg *msg)
log_free(buf);
}
}
} else if (IS_ENABLED(CONFIG_USERSPACE) &&
(log_msg_level_get(msg) != LOG_LEVEL_INTERNAL_RAW_STRING)) {
/*
* When userspace support is enabled, the hex message metadata
* might be located in log_strdup() memory pool.
*/
const char *str = log_msg_str_get(msg);
if (log_is_strdup(str)) {
log_free((void *)(str));
}
}
if (msg->hdr.params.generic.ext == 1) {

5
subsys/testsuite/ztest/include/syscalls/log_core.h Normal file
View file

@ -0,0 +1,5 @@
/*
* Copyright (c) 2019 Nordic Semiconductor ASA
*
* SPDX-License-Identifier: Apache-2.0
*/

5
subsys/testsuite/ztest/include/syscalls/log_ctrl.h Normal file
View file

@ -0,0 +1,5 @@
/*
* Copyright (c) 2019 Nordic Semiconductor ASA
*
* SPDX-License-Identifier: Apache-2.0
*/