logging: Refactor in preparation for logging v2

Refactor and cleanup in preparation for v2.

Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
This commit is contained in:
Krzysztof Chruscinski 2021-01-28 09:09:29 +01:00 committed by Anas Nashif
commit ba1aa75c66
7 changed files with 196 additions and 165 deletions

View file

@ -151,7 +151,8 @@ extern "C" {
* used.
*/
#define Z_LOG_STR(...) "%s: " GET_ARG_N(1, __VA_ARGS__), __func__\
#define Z_LOG_STR(...) "%s: " GET_ARG_N(1, __VA_ARGS__), \
(const char *)__func__\
COND_CODE_0(NUM_VA_ARGS_LESS_1(__VA_ARGS__),\
(),\
(, GET_ARGS_LESS_N(1, __VA_ARGS__))\
@ -162,7 +163,7 @@ extern "C" {
/****************** Internal macros for log frontend **************************/
/******************************************************************************/
/**@brief Second stage for Z_LOG_NARGS_POSTFIX */
#define _LOG_NARGS_POSTFIX_IMPL( \
#define Z_LOG_NARGS_POSTFIX_IMPL( \
_ignored, \
_0, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, \
_11, _12, _13, _14, N, ...) N
@ -176,22 +177,38 @@ extern "C" {
* @retval Postfix, number of arguments or _LONG when more than 3 arguments.
*/
#define Z_LOG_NARGS_POSTFIX(...) \
_LOG_NARGS_POSTFIX_IMPL(__VA_ARGS__, LONG, LONG, LONG, LONG, LONG, \
Z_LOG_NARGS_POSTFIX_IMPL(__VA_ARGS__, LONG, LONG, LONG, LONG, LONG, \
LONG, LONG, LONG, LONG, LONG, LONG, LONG, 3, 2, 1, 0, ~)
#define Z_LOG_INTERNAL_X(N, ...) UTIL_CAT(_LOG_INTERNAL_, N)(__VA_ARGS__)
#define __LOG_INTERNAL(is_user_context, _src_level, ...) \
do { \
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__), \
_src_level, __VA_ARGS__);\
} \
} while (false)
#define Z_LOG_INTERNAL2(is_user_context, _src_level, ...) do { \
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__), \
_src_level, __VA_ARGS__); \
} \
} while (false)
#define Z_LOG_INTERNAL(is_user_context, _level, _source, ...) do { \
uint16_t src_id = \
IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \
LOG_DYNAMIC_ID_GET(_source) : LOG_CONST_ID_GET(_source);\
struct log_msg_ids src_level = { \
.level = _level, \
.domain_id = CONFIG_LOG_DOMAIN_ID, \
.source_id = src_id \
}; \
if (BIT(_level) & LOG_FUNCTION_PREFIX_MASK) {\
Z_LOG_INTERNAL2(is_user_context, src_level, \
Z_LOG_STR(__VA_ARGS__)); \
} else { \
Z_LOG_INTERNAL2(is_user_context, src_level, __VA_ARGS__); \
} \
} while (0)
#define _LOG_INTERNAL_0(_src_level, _str) \
log_0(_str, _src_level)
@ -228,9 +245,9 @@ extern "C" {
) \
))
/******************************************************************************/
/****************** Defiinitions used by minimal logging **********************/
/******************************************************************************/
/*****************************************************************************/
/****************** Defiinitions used by minimal logging *********************/
/*****************************************************************************/
void z_log_minimal_hexdump_print(int level, const void *data, size_t size);
void z_log_minimal_vprintk(const char *fmt, va_list ap);
void z_log_minimal_printk(const char *fmt, ...);
@ -256,118 +273,95 @@ static inline char z_log_minimal_level_to_char(int level)
return '?';
}
}
/******************************************************************************/
/****************** Macros for standard logging *******************************/
/******************************************************************************/
#define __LOG(_level, _id, _filter, ...) \
do { \
if (Z_LOG_CONST_LEVEL_CHECK(_level)) { \
bool is_user_context = k_is_user_context(); \
\
if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \
Z_LOG_TO_PRINTK(_level, __VA_ARGS__); \
} else if (LOG_CHECK_CTX_LVL_FILTER(is_user_context, \
_level, _filter)) { \
struct log_msg_ids src_level = { \
.level = _level, \
.domain_id = CONFIG_LOG_DOMAIN_ID, \
.source_id = _id \
}; \
\
if ((BIT(_level) & \
LOG_FUNCTION_PREFIX_MASK) != 0U) { \
__LOG_INTERNAL(is_user_context, \
src_level, \
Z_LOG_STR(__VA_ARGS__));\
} else { \
__LOG_INTERNAL(is_user_context, \
src_level, \
__VA_ARGS__); \
} \
} else { \
} \
} \
if (false) { \
/* Arguments checker present but never evaluated.*/ \
/* Placed here to ensure that __VA_ARGS__ are*/ \
/* evaluated once when log is enabled.*/ \
log_printf_arg_checker(__VA_ARGS__); \
} \
} while (false)
/*****************************************************************************/
/****************** Macros for standard logging ******************************/
/*****************************************************************************/
#define Z_LOG2(_level, _source, ...) do { \
if (!Z_LOG_CONST_LEVEL_CHECK(_level)) { \
break; \
} \
if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \
Z_LOG_TO_PRINTK(_level, __VA_ARGS__); \
break; \
} \
\
bool is_user_context = k_is_user_context(); \
uint32_t filters = IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \
((struct log_source_dynamic_data *)(void *)(_source))->filters : 0;\
if (!LOG_CHECK_CTX_LVL_FILTER(is_user_context, _level, filters)) { \
break; \
} \
\
Z_LOG_INTERNAL(is_user_context, _level, _source, __VA_ARGS__);\
if (false) { \
/* Arguments checker present but never evaluated.*/ \
/* Placed here to ensure that __VA_ARGS__ are*/ \
/* evaluated once when log is enabled.*/ \
z_log_printf_arg_checker(__VA_ARGS__); \
} \
} while (false)
#define Z_LOG(_level, ...) \
__LOG(_level, \
(uint16_t)LOG_CURRENT_MODULE_ID(), \
LOG_CURRENT_DYNAMIC_DATA_ADDR(), \
__VA_ARGS__)
#define Z_LOG_INSTANCE(_level, _inst, ...) \
__LOG(_level, \
#define Z_LOG(_level, ...) \
Z_LOG2(_level, \
IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \
LOG_DYNAMIC_ID_GET(_inst) : \
LOG_CONST_ID_GET(_inst), \
_inst, \
(void *)__log_current_dynamic_data : \
(void *)__log_current_const_data, \
__VA_ARGS__)
#define Z_LOG_INSTANCE(_level, _inst, ...) Z_LOG2(_level, _inst, __VA_ARGS__)
/******************************************************************************/
/****************** Macros for hexdump logging ********************************/
/******************************************************************************/
#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length, _str) \
do { \
if (Z_LOG_CONST_LEVEL_CHECK(_level)) { \
bool is_user_context = k_is_user_context(); \
\
if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \
Z_LOG_TO_PRINTK(_level, "%s", _str); \
z_log_minimal_hexdump_print(_level, \
(const char *)_data, \
_length); \
} else if (LOG_CHECK_CTX_LVL_FILTER(is_user_context, \
_level, _filter)) { \
struct log_msg_ids src_level = { \
.level = _level, \
.domain_id = CONFIG_LOG_DOMAIN_ID, \
.source_id = _id, \
}; \
\
if (is_user_context) { \
log_hexdump_from_user(src_level, _str, \
(const char *)_data, \
_length); \
} else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \
log_hexdump_sync(src_level, _str, \
(const char *)_data, \
_length); \
} else { \
log_hexdump(_str, (const char *)_data, \
_length, \
src_level); \
} \
} else { \
} \
} \
} while (false)
#define Z_LOG_HEXDUMP(_level, _data, _length, _str) \
__LOG_HEXDUMP(_level, \
(uint16_t)LOG_CURRENT_MODULE_ID(), \
LOG_CURRENT_DYNAMIC_DATA_ADDR(), \
_data, _length, _str)
/*****************************************************************************/
/****************** Macros for hexdump logging *******************************/
/*****************************************************************************/
#define Z_LOG_HEXDUMP2(_level, _source, _data, _len, ...) do { \
const char *_str = GET_ARG_N(1, __VA_ARGS__); \
if (!Z_LOG_CONST_LEVEL_CHECK(_level)) { \
break; \
} \
bool is_user_context = k_is_user_context(); \
uint32_t filters = IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \
((struct log_source_dynamic_data *)(void *)(_source))->filters : 0;\
\
if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \
Z_LOG_TO_PRINTK(_level, "%s", _str); \
z_log_minimal_hexdump_print(_level, \
(const char *)_data, _len);\
break; \
} \
if (!LOG_CHECK_CTX_LVL_FILTER(is_user_context, _level, filters)) { \
break; \
} \
uint16_t src_id = \
IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \
LOG_DYNAMIC_ID_GET(_source) : LOG_CONST_ID_GET(_source);\
struct log_msg_ids src_level = { \
.level = _level, \
.domain_id = CONFIG_LOG_DOMAIN_ID, \
.source_id = src_id, \
}; \
if (is_user_context) { \
log_hexdump_from_user(src_level, _str, \
(const char *)_data, _len); \
} else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \
log_hexdump_sync(src_level, _str, (const char *)_data, _len); \
} else { \
log_hexdump(_str, (const char *)_data, _len, src_level); \
} \
} while (false)
#define Z_LOG_HEXDUMP(_level, _data, _length, ...) \
Z_LOG_HEXDUMP2(_level, IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \
(void *)__log_current_dynamic_data : \
(void *)__log_current_const_data, \
_data, _length, __VA_ARGS__)
#define Z_LOG_HEXDUMP_INSTANCE(_level, _inst, _data, _length, _str) \
__LOG_HEXDUMP(_level, \
IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \
LOG_DYNAMIC_ID_GET(_inst) : \
LOG_CONST_ID_GET(_inst), \
_inst, \
_data, \
_length, \
_str)
Z_LOG_HEXDUMP2(_level, _inst, _data, _length, _str)
/******************************************************************************/
/****************** Filtering macros ******************************************/
/******************************************************************************/
/*****************************************************************************/
/****************** Filtering macros *****************************************/
/*****************************************************************************/
/** @brief Number of bits used to encode log level. */
#define LOG_LEVEL_BITS 3U
@ -409,9 +403,9 @@ static inline char z_log_minimal_level_to_char(int level)
#define LOG_CHECK_CTX_LVL_FILTER(ctx, _level, _filter) \
(ctx || (_level <= LOG_RUNTIME_FILTER(_filter)))
#define LOG_RUNTIME_FILTER(_filter) \
LOG_FILTER_SLOT_GET(&(_filter)->filters, LOG_FILTER_AGGR_SLOT_IDX)
LOG_FILTER_SLOT_GET(&_filter, LOG_FILTER_AGGR_SLOT_IDX)
#else
#define LOG_CHECK_CTX_LVL_FILTER(ctx, _level, _filter) (true)
#define LOG_CHECK_CTX_LVL_FILTER(ctx, _level, _filter) ((true) | _filter)
#define LOG_RUNTIME_FILTER(_filter) LOG_LEVEL_DBG
#endif
@ -430,6 +424,20 @@ enum log_strdup_action {
LOG_STRDUP_CHECK_EXEC/**< Duplicate RAM strings, if not dupl. before.*/
};
#define Z_LOG_PRINTK(...) do { \
if (IS_ENABLED(CONFIG_LOG_MINIMAL) || !IS_ENABLED(CONFIG_LOG2)) { \
z_log_minimal_printk(__VA_ARGS__); \
break; \
} \
int _mode; \
if (0) {\
z_log_printf_arg_checker(__VA_ARGS__); \
} \
Z_LOG_MSG2_CREATE(!IS_ENABLED(CONFIG_USERSPACE), _mode, \
CONFIG_LOG_DOMAIN_ID, NULL, \
LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0, __VA_ARGS__);\
} while (0)
/** @brief Get name of the log source.
*
* @param source_id Source ID.
@ -508,7 +516,7 @@ static inline uint32_t log_dynamic_source_id(struct log_source_dynamic_data *dat
/** @brief Dummy function to trigger log messages arguments type checking. */
static inline __printf_like(1, 2)
void log_printf_arg_checker(const char *fmt, ...)
void z_log_printf_arg_checker(const char *fmt, ...)
{
ARG_UNUSED(fmt);
}
@ -660,7 +668,20 @@ uint32_t log_get_strdup_longest_string(void);
/** @brief Indicate to the log core that one log message has been dropped.
*/
void log_dropped(void);
void z_log_dropped(void);
/** @brief Read and clear current drop indications counter.
*
* @return Dropped count.
*/
uint32_t z_log_dropped_read_and_clear(void);
/** @brief Check if there are any pending drop notifications.
*
* @retval true Pending unreported drop indications.
* @retval false No pending unreported drop indications.
*/
bool z_log_dropped_pending(void);
/** @brief Log a message from user mode context.
*
@ -674,6 +695,9 @@ void log_dropped(void);
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(uint32_t src_level_val, const char *str);
/**
* @brief Create mask with occurences of a string format specifiers (%s).
*
@ -687,9 +711,6 @@ void __printf_like(2, 3) log_from_user(struct log_msg_ids src_level,
*/
uint32_t z_log_get_s_mask(const char *str, uint32_t nargs);
/* Internal function used by log_from_user(). */
__syscall void z_log_string_from_user(uint32_t src_level_val, const char *str);
/** @brief Log binary data (displayed as hexdump) from user mode context.
*
* @note This function is intended to be used internally
@ -760,7 +781,7 @@ static inline log_arg_t z_log_do_strdup(uint32_t msk, uint32_t idx,
enum log_strdup_action action)
{
#ifndef CONFIG_LOG_MINIMAL
char *log_strdup(const char *str);
char *z_log_strdup(const char *str);
if (msk & (1 << idx)) {
const char *str = (const char *)param;
@ -770,7 +791,7 @@ static inline log_arg_t z_log_do_strdup(uint32_t msk, uint32_t idx,
* if already not duplicated.
*/
if (action == LOG_STRDUP_EXEC || !log_is_strdup(str)) {
param = (log_arg_t)log_strdup(str);
param = (log_arg_t)z_log_strdup(str);
}
}
#else
@ -792,7 +813,7 @@ do { \
_LOG_INTERNAL_0(_src_level, _str); \
} else { \
uint32_t mask = (_strdup_action != LOG_STRDUP_SKIP) ? \
z_log_get_s_mask(_str, _argnum) \
z_log_get_s_mask(_str, _argnum) \
: 0; \
\
if (_argnum == 1) { \

View file

@ -106,11 +106,11 @@ uint32_t log_src_cnt_get(uint32_t domain_id);
/** @brief Get name of the source (module or instance).
*
* @param domain_id Domain ID.
* @param src_id Source ID.
* @param source_id Source ID.
*
* @return Source name or NULL if invalid arguments.
*/
const char *log_source_name_get(uint32_t domain_id, uint32_t src_id);
const char *log_source_name_get(uint32_t domain_id, uint32_t source_id);
/** @brief Get name of the domain.
*
@ -125,29 +125,28 @@ const char *log_domain_name_get(uint32_t domain_id);
*
* @param backend Backend instance.
* @param domain_id ID of the domain.
* @param src_id Source (module or instance) ID.
* @param source_id Source (module or instance) ID.
* @param runtime True for runtime filter or false for compiled in.
*
* @return Severity level.
*/
uint32_t log_filter_get(struct log_backend const *const backend,
uint32_t domain_id, uint32_t src_id, bool runtime);
uint32_t domain_id, int16_t source_id, bool runtime);
/**
* @brief Set filter on given source for the provided backend.
*
* @param backend Backend instance. NULL for all backends.
* @param domain_id ID of the domain.
* @param src_id Source (module or instance) ID.
* @param source_id Source (module or instance) ID.
* @param level Severity level.
*
* @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.
*/
__syscall uint32_t log_filter_set(struct log_backend const *const backend,
uint32_t domain_id,
uint32_t src_id,
uint32_t level);
uint32_t domain_id, int16_t source_id,
uint32_t level);
/**
*

View file

@ -69,15 +69,16 @@ static uint32_t timestamp_freq(void)
*
* @return Source ID.
*/
static int log_source_id_get(const char *name)
static int16_t log_source_id_get(const char *name)
{
for (int i = 0; i < log_src_cnt_get(CONFIG_LOG_DOMAIN_ID); i++) {
for (int16_t i = 0; i < log_src_cnt_get(CONFIG_LOG_DOMAIN_ID); i++) {
if (strcmp(log_source_name_get(CONFIG_LOG_DOMAIN_ID, i), name)
== 0) {
return i;
}
}
return -1;
}

View file

@ -95,8 +95,6 @@ static int log_status(const struct shell *shell,
uint32_t modules_cnt = log_sources_count();
uint32_t dynamic_lvl;
uint32_t compiled_lvl;
uint32_t i;
if (!log_backend_is_active(backend)) {
shell_warn(shell, "Logs are halted!");
@ -107,7 +105,7 @@ static int log_status(const struct shell *shell,
shell_fprintf(shell, SHELL_NORMAL,
"----------------------------------------------------------\r\n");
for (i = 0U; i < modules_cnt; i++) {
for (int16_t i = 0U; i < modules_cnt; i++) {
dynamic_lvl = log_filter_get(backend, CONFIG_LOG_DOMAIN_ID,
i, true);
compiled_lvl = log_filter_get(backend, CONFIG_LOG_DOMAIN_ID,

View file

@ -636,6 +636,7 @@ static bool msg_filter_check(struct log_backend const *backend,
if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
uint32_t backend_level;
uint32_t msg_level;
(struct log_source_dynamic_data *)
backend_level = log_filter_get(backend,
log_msg_domain_id_get(msg),
@ -674,7 +675,7 @@ static void msg_process(struct log_msg *msg, bool bypass)
void dropped_notify(void)
{
uint32_t dropped = atomic_set(&dropped_cnt, 0);
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);
@ -702,7 +703,7 @@ bool z_impl_log_process(bool bypass)
msg_process(msg, bypass);
}
if (!bypass && dropped_cnt) {
if (!bypass && z_log_dropped_pending()) {
dropped_notify();
}
@ -730,11 +731,21 @@ uint32_t z_vrfy_log_buffered_cnt(void)
#include <syscalls/log_buffered_cnt_mrsh.c>
#endif
void log_dropped(void)
void z_log_dropped(void)
{
atomic_inc(&dropped_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;
}
uint32_t log_src_cnt_get(uint32_t domain_id)
{
return log_sources_count();
@ -763,16 +774,15 @@ static uint32_t max_filter_get(uint32_t filters)
}
uint32_t z_impl_log_filter_set(struct log_backend const *const backend,
uint32_t domain_id,
uint32_t src_id,
uint32_t level)
uint32_t domain_id, int16_t source_id,
uint32_t level)
{
__ASSERT_NO_MSG(src_id < log_sources_count());
__ASSERT_NO_MSG(source_id < log_sources_count());
if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
uint32_t new_aggr_filter;
uint32_t *filters = log_dynamic_filters_get(src_id);
uint32_t *filters = log_dynamic_filters_get(source_id);
if (backend == NULL) {
struct log_backend const *iter_backend;
@ -783,14 +793,14 @@ uint32_t z_impl_log_filter_set(struct log_backend const *const backend,
iter_backend = log_backend_get(i);
current = log_filter_set(iter_backend,
domain_id,
src_id, level);
source_id, level);
max = MAX(current, max);
}
level = max;
} else {
uint32_t max = log_filter_get(backend, domain_id,
src_id, false);
source_id, false);
level = MIN(level, max);
@ -815,7 +825,7 @@ uint32_t z_impl_log_filter_set(struct log_backend const *const backend,
#ifdef CONFIG_USERSPACE
uint32_t z_vrfy_log_filter_set(struct log_backend const *const backend,
uint32_t domain_id,
uint32_t src_id,
int16_t src_id,
uint32_t level)
{
Z_OOPS(Z_SYSCALL_VERIFY_MSG(backend == 0,
@ -873,20 +883,22 @@ void log_backend_disable(struct log_backend const *const backend)
}
uint32_t log_filter_get(struct log_backend const *const backend,
uint32_t domain_id,
uint32_t src_id,
bool runtime)
uint32_t domain_id, int16_t source_id, bool runtime)
{
__ASSERT_NO_MSG(src_id < log_sources_count());
__ASSERT_NO_MSG(source_id < log_sources_count());
if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) && runtime) {
uint32_t *filters = log_dynamic_filters_get(src_id);
if (source_id < 0) {
return LOG_LEVEL_DBG;
}
uint32_t *filters = log_dynamic_filters_get(source_id);
return LOG_FILTER_SLOT_GET(filters,
log_backend_id_get(backend));
} else {
return log_compiled_level_get(src_id);
}
return log_compiled_level_get(source_id);
}
char *log_strdup(const char *str)

View file

@ -168,13 +168,13 @@ union log_msg_chunk *log_msg_no_space_handle(void)
if (IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
do {
more = log_process(true);
log_dropped();
z_log_dropped();
err = k_mem_slab_alloc(&log_msg_pool,
(void **)&msg,
K_NO_WAIT);
} while ((err != 0) && more);
} else {
log_dropped();
z_log_dropped();
}
return msg;

View file

@ -136,10 +136,10 @@ static uint32_t timestamp_get(void)
*
* @return Source ID.
*/
static int log_source_id_get(const char *name)
static int16_t log_source_id_get(const char *name)
{
for (int i = 0; i < log_src_cnt_get(CONFIG_LOG_DOMAIN_ID); i++) {
for (int16_t i = 0; i < log_src_cnt_get(CONFIG_LOG_DOMAIN_ID); i++) {
if (strcmp(log_source_name_get(CONFIG_LOG_DOMAIN_ID, i), name)
== 0) {
return i;