diff --git a/boards/arm/bbc_microbit/bbc_microbit_defconfig b/boards/arm/bbc_microbit/bbc_microbit_defconfig index ad63de932f0..456f033791e 100644 --- a/boards/arm/bbc_microbit/bbc_microbit_defconfig +++ b/boards/arm/bbc_microbit/bbc_microbit_defconfig @@ -20,3 +20,6 @@ CONFIG_UART_CONSOLE=y # bluetooth CONFIG_BT=y CONFIG_BT_CTLR=y + +# logging +CONFIG_LOG_BUFFER_SIZE=128 diff --git a/include/linker/common-ram.ld b/include/linker/common-ram.ld index c45c6f73509..e5db37e0370 100644 --- a/include/linker/common-ram.ld +++ b/include/linker/common-ram.ld @@ -15,6 +15,13 @@ SHELL_INIT_SECTIONS() } GROUP_DATA_LINK_IN(RAMABLE_REGION, ROMABLE_REGION) + SECTION_DATA_PROLOGUE(log_dynamic_sections, (OPTIONAL),) + { + __log_dynamic_start = .; + KEEP(*(SORT(.log_dynamic_*))); + __log_dynamic_end = .; + } GROUP_DATA_LINK_IN(RAMABLE_REGION, ROMABLE_REGION) + SECTION_DATA_PROLOGUE(_static_thread_area, (OPTIONAL), SUBALIGN(4)) { _static_thread_data_list_start = .; diff --git a/include/linker/common-rom.ld b/include/linker/common-rom.ld index 4b987cec62c..59bdd0ea54c 100644 --- a/include/linker/common-rom.ld +++ b/include/linker/common-rom.ld @@ -59,3 +59,17 @@ _bt_settings_end = .; } GROUP_LINK_IN(ROMABLE_REGION) #endif + + SECTION_DATA_PROLOGUE(log_const_sections, (OPTIONAL),) + { + __log_const_start = .; + KEEP(*(SORT(.log_const_*))); + __log_const_end = .; + } GROUP_LINK_IN(ROMABLE_REGION) + + SECTION_DATA_PROLOGUE(log_backends_sections, (OPTIONAL),) + { + __log_backends_start = .; + KEEP(*(".log_backends")); + __log_backends_end = .; + } GROUP_LINK_IN(ROMABLE_REGION) diff --git a/include/linker/linker-defs.h b/include/linker/linker-defs.h index 19be634715f..12fb49bfa82 100644 --- a/include/linker/linker-defs.h +++ b/include/linker/linker-defs.h @@ -107,6 +107,11 @@ KEEP(*(".shell_cmd_*")); \ __shell_cmd_end = .; \ +/* + * link in shell initialization objects for all modules that use shell and + * their shell commands are automatically initialized by the kernel. + */ + #ifdef CONFIG_APPLICATION_MEMORY #ifndef NUM_KERNEL_OBJECT_FILES diff --git a/include/logging/log.h b/include/logging/log.h new file mode 100644 index 00000000000..477abdd9405 --- /dev/null +++ b/include/logging/log.h @@ -0,0 +1,282 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#ifndef LOG_H_ +#define LOG_H_ + +#include +#include + +#ifdef __cplusplus +extern "C" { +#endif + +#define LOG_LEVEL_NONE 0 +#define LOG_LEVEL_ERR 1 +#define LOG_LEVEL_WRN 2 +#define LOG_LEVEL_INF 3 +#define LOG_LEVEL_DBG 4 + +/** + * @brief Writes an ERROR level message to the log. + * + * @details It's meant to report severe errors, such as those from which it's + * not possible to recover. + * + * @param ... A string optionally containing printk valid conversion specifier, + * followed by as many values as specifiers. + */ +#define LOG_ERR(...) _LOG(LOG_LEVEL_ERR, __VA_ARGS__) + + +/** + * @brief Writes a WARNING level message to the log. + * + * @details It's meant to register messages related to unusual situations that + * are not necessarily errors. + * + * @param ... A string optionally containing printk valid conversion specifier, + * followed by as many values as specifiers. + */ +#define LOG_WRN(...) _LOG(LOG_LEVEL_WRN, __VA_ARGS__) + +/** + * @brief Writes an INFO level message to the log. + * + * @details It's meant to write generic user oriented messages. + * + * @param ... A string optionally containing printk valid conversion specifier, + * followed by as many values as specifiers. + */ +#define LOG_INF(...) _LOG(LOG_LEVEL_INF, __VA_ARGS__) + +/** + * @brief Writes a DEBUG level message to the log. + * + * @details It's meant to write developer oriented information. + * + * @param ... A string optionally containing printk valid conversion specifier, + * followed by as many values as specifiers. + */ +#define LOG_DBG(...) _LOG(LOG_LEVEL_DBG, __VA_ARGS__) + +/** + * @brief Writes an ERROR level message associated with the instance to the log. + * + * Message is associated with specific instance of the module which has + * independent filtering settings (if runtime filtering is enabled) and + * message prefix (\.\). It's meant to report + * severe errors, such as those from which it's not possible to recover. + * + * @param _log_inst Pointer to the log structure associated with the instance. + * @param ... A string optionally containing printk valid conversion specifier, + * followed by as many values as specifiers. + */ +#define LOG_INST_ERR(_log_inst, ...) \ + _LOG_INSTANCE(LOG_LEVEL_ERR, _log_inst, __VA_ARGS__) + +/** + * @brief Writes a WARNING level message associated with the instance to the + * log. + * + * Message is associated with specific instance of the module which has + * independent filtering settings (if runtime filtering is enabled) and + * message prefix (\.\). It's meant to register + * messages related to unusual situations that are not necessarily errors. + * + * @param _log_inst Pointer to the log structure associated with the instance. + * @param ... A string optionally containing printk valid conversion + * specifier, followed by as many values as specifiers. + */ +#define LOG_INST_WRN(_log_inst, ...) \ + _LOG_INSTANCE(LOG_LEVEL_WRN, _log_inst, __VA_ARGS__) + +/** + * @brief Writes an INFO level message associated with the instance to the log. + * + * Message is associated with specific instance of the module which has + * independent filtering settings (if runtime filtering is enabled) and + * message prefix (\.\). It's meant to write + * generic user oriented messages. + * + * @param _log_inst Pointer to the log structure associated with the instance. + * @param ... A string optionally containing printk valid conversion specifier, + * followed by as many values as specifiers. + */ +#define LOG_INST_INF(_log_inst, ...) \ + _LOG_INSTANCE(LOG_LEVEL_INF, _log_inst, __VA_ARGS__) + +/** + * @brief Writes a DEBUG level message associated with the instance to the log. + * + * Message is associated with specific instance of the module which has + * independent filtering settings (if runtime filtering is enabled) and + * message prefix (\.\). It's meant to write + * developer oriented information. + * + * @param _log_inst Pointer to the log structure associated with the instance. + * @param ... A string optionally containing printk valid conversion specifier, + * followed by as many values as specifiers. + */ +#define LOG_INST_DBG(_log_inst, ...) \ + _LOG_INSTANCE(LOG_LEVEL_DBG, _log_inst, __VA_ARGS__) + +/** + * @brief Writes an ERROR level hexdump message to the log. + * + * @details It's meant to report severe errors, such as those from which it's + * not possible to recover. + * + * @param data Pointer to the data to be logged. + * @param length Length of data (in bytes). + */ +#define LOG_HEXDUMP_ERR(data, length) \ + _LOG_HEXDUMP(LOG_LEVEL_ERR, data, length) + +/** + * @brief Writes a WARNING level message to the log. + * + * @details It's meant to register messages related to unusual situations that + * are not necessarily errors. + * + * @param data Pointer to the data to be logged. + * @param length Length of data (in bytes). + */ +#define LOG_HEXDUMP_WRN(data, length) \ + _LOG_HEXDUMP(LOG_LEVEL_WRN, data, length) + +/** + * @brief Writes an INFO level message to the log. + * + * @details It's meant to write generic user oriented messages. + * + * @param data Pointer to the data to be logged. + * @param length Length of data (in bytes). + */ +#define LOG_HEXDUMP_INF(data, length) \ + _LOG_HEXDUMP(LOG_LEVEL_INF, data, length) + +/** + * @brief Writes a DEBUG level message to the log. + * + * @details It's meant to write developer oriented information. + * + * @param data Pointer to the data to be logged. + * @param length Length of data (in bytes). + */ +#define LOG_HEXDUMP_DBG(data, length) \ + _LOG_HEXDUMP(LOG_LEVEL_DBG, data, length) + +/** + * @brief Writes an ERROR hexdump message associated with the instance to the + * log. + * + * Message is associated with specific instance of the module which has + * independent filtering settings (if runtime filtering is enabled) and + * message prefix (\.\). It's meant to report + * severe errors, such as those from which it's not possible to recover. + * + * @param _log_inst Pointer to the log structure associated with the instance. + * @param data Pointer to the data to be logged. + * @param length Length of data (in bytes). + */ +#define LOG_INST_HEXDUMP_ERR(_log_inst, data, length) \ + _LOG_HEXDUMP_INSTANCE(LOG_LEVEL_ERR, _log_inst, data, length) + +/** + * @brief Writes a WARNING level hexdump message associated with the instance to + * the log. + * + * @details It's meant to register messages related to unusual situations that + * are not necessarily errors. + * + * @param _log_inst Pointer to the log structure associated with the instance. + * @param data Pointer to the data to be logged. + * @param length Length of data (in bytes). + */ +#define LOG_INST_HEXDUMP_WRN(_log_inst, data, length) \ + _LOG_HEXDUMP_INSTANCE(LOG_LEVEL_WRN, _log_inst, data, length) + +/** + * @brief Writes an INFO level hexdump message associated with the instance to + * the log. + * + * @details It's meant to write generic user oriented messages. + * + * @param _log_inst Pointer to the log structure associated with the instance. + * @param data Pointer to the data to be logged. + * @param length Length of data (in bytes). + */ +#define LOG_INST_HEXDUMP_INF(_log_inst, data, length) \ + _LOG_HEXDUMP_INSTANCE(LOG_LEVEL_INF, _log_inst, data, length) + +/** + * @brief Writes a DEBUG level hexdump message associated with the instance to + * the log. + * + * @details It's meant to write developer oriented information. + * + * @param _log_inst Pointer to the log structure associated with the instance. + * @param _data Pointer to the data to be logged. + * @param _length Length of data (in bytes). + */ +#define LOG_INST_HEXDUMP_DBG(_log_inst, _data, _length) \ + _LOG_HEXDUMP_INSTANCE(LOG_LEVEL_DBG, _log_inst, _data, _length) + +/** + * @brief Writes an formatted string to the log. + * + * @details Conditionally compiled (see CONFIG_LOG_PRINTK). Function provides + * printk functionality. It is inefficient compared to standard logging + * because string formatting is performed in the call context and not deferred + * to the log processing context (@ref log_process). + * + * @param fmt Formatted string to output. + * @param ap Variable parameters. + * + * return Number of bytes written. + */ +int log_printk(const char *fmt, va_list ap); + +/* Register a module unless explicitly skipped (using LOG_SKIP_MODULE_REGISTER). + * Skipping may be used in 2 cases: + * - Module consists of more than one file and must be registered only by one + * file. + * - Instance logging is used and there is no need to create module entry. + */ + +#if defined(LOG_MODULE_NAME) && \ + ((defined(LOG_LEVEL) && (LOG_LEVEL > LOG_LEVEL_NONE)) || \ + (!defined(LOG_LEVEL) && (CONFIG_LOG_DEFAULT_LEVEL > LOG_LEVEL_NONE))) +#if CONFIG_LOG_RUNTIME_FILTERING +#define LOG_MODULE_REGISTER() \ + _LOG_CONST_ITEM_REGISTER(LOG_MODULE_NAME, \ + STRINGIFY(LOG_MODULE_NAME), \ + _LOG_RESOLVED_LEVEL(LOG_LEVEL, \ + CONFIG_LOG_DEFAULT_LEVEL)); \ + struct log_source_dynamic_data LOG_ITEM_DYNAMIC_DATA(LOG_MODULE_NAME) \ + __attribute__ ((section("." STRINGIFY( \ + LOG_ITEM_DYNAMIC_DATA(LOG_MODULE_NAME)))) \ + ) \ + __attribute__((used)) +#else /*CONFIG_LOG_RUNTIME_FILTERING*/ + +#define LOG_MODULE_REGISTER() \ + _LOG_CONST_ITEM_REGISTER(LOG_MODULE_NAME, \ + STRINGIFY(LOG_MODULE_NAME), \ + _LOG_RESOLVED_LEVEL(LOG_LEVEL, \ + CONFIG_LOG_DEFAULT_LEVEL)) +#endif /*CONFIG_LOG_RUNTIME_FILTERING*/ + +#else /* LOG enabled for the module. */ +#define LOG_MODULE_REGISTER() /* Empty */ +#endif + +#ifdef __cplusplus +} +#endif + +#endif /* LOG_H_ */ diff --git a/include/logging/log_backend.h b/include/logging/log_backend.h new file mode 100644 index 00000000000..300b67a9dac --- /dev/null +++ b/include/logging/log_backend.h @@ -0,0 +1,191 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef LOG_BACKEND_H +#define LOG_BACKEND_H + +#include +#include +#ifdef __cplusplus +extern "C" { +#endif + +/* Forward declaration of the log_backend type. */ +struct log_backend; + +/** + * @brief Logger backend API. + */ +struct log_backend_api { + void (*put)(const struct log_backend *const backend, + struct log_msg *msg); + + void (*panic)(const struct log_backend *const backend); +}; + +/** + * @brief Logger backend control block. + */ +struct log_backend_control_block { + void *ctx; + u8_t id; + bool active; +}; + +/** + * @brief Logger backend structure. + */ +struct log_backend { + const struct log_backend_api *api; + struct log_backend_control_block *cb; + const char *name; +}; + +extern const struct log_backend __log_backends_start[0]; +extern const struct log_backend __log_backends_end[0]; + +/** + * @brief Macro for creating a logger backend instance. + * + * @param _name Name of the backend instance. + * @param _api Logger backend API. + */ +#define LOG_BACKEND_DEFINE(_name, _api) \ + static struct log_backend_control_block UTIL_CAT(backend_cb_, _name) = \ + { \ + .active = false, \ + .id = 0, \ + }; \ + static const struct log_backend _name \ + __attribute__ ((section(".log_backends"))) __attribute__((used)) = \ + { \ + .api = &_api, \ + .cb = &UTIL_CAT(backend_cb_, _name), \ + .name = STRINGIFY(_name) \ + } + + +/** + * @brief Function for putting message with log entry to the backend. + * + * @param[in] backend Pointer to the backend instance. + * @param[in] msg Pointer to message with log entry. + */ +static inline void log_backend_put(const struct log_backend *const backend, + struct log_msg *msg) +{ + assert(backend); + assert(msg); + backend->api->put(backend, msg); +} + +/** + * @brief Function for reconfiguring backend to panic mode. + * + * @param[in] backend Pointer to the backend instance. + */ +static inline void log_backend_panic(const struct log_backend *const backend) +{ + assert(backend); + backend->api->panic(backend); +} + +/** + * @brief Function for setting backend id. + * + * @note It is used internally by the logger. + * + * @param backend Pointer to the backend instance. + * @param id ID. + */ +static inline void log_backend_id_set(const struct log_backend *const backend, + u8_t id) +{ + assert(backend); + backend->cb->id = id; +} + +/** + * @brief Function for getting backend id. + * + * @note It is used internally by the logger. + * + * @param[in] backend Pointer to the backend instance. + * @return Id. + */ +static inline u8_t log_backend_id_get(const struct log_backend *const backend) +{ + assert(backend); + return backend->cb->id; +} + +/** + * @brief Function for getting backend. + * + * @param[in] idx Pointer to the backend instance. + * + * @return Pointer to the backend instance. + */ +static inline const struct log_backend *log_backend_get(u32_t idx) +{ + return &__log_backends_start[idx]; +} + +/** + * @brief Function for getting number of backends. + * + * @return Number of backends. + */ +static inline int log_backend_count_get(void) +{ + return ((void *)__log_backends_end - (void *)__log_backends_start) / + sizeof(struct log_backend); +} + +/** + * @brief Function for activating backend. + * + * @param[in] backend Pointer to the backend instance. + * @param[in] ctx User context. + */ +static inline void log_backend_activate(const struct log_backend *const backend, + void *ctx) +{ + assert(backend); + backend->cb->ctx = ctx; + backend->cb->active = true; +} + +/** + * @brief Function for deactivating backend. + * + * @param[in] backend Pointer to the backend instance. + */ +static inline void log_backend_deactivate( + const struct log_backend *const backend) +{ + assert(backend); + backend->cb->active = false; +} + +/** + * @brief Function for checking state of the backend. + * + * @param[in] backend Pointer to the backend instance. + * + * @return True if backend is active, false otherwise. + */ +static inline bool log_backend_is_active( + const struct log_backend *const backend) +{ + assert(backend); + return backend->cb->active; +} + +#ifdef __cplusplus +} +#endif + +#endif /* LOG_BACKEND_H */ diff --git a/include/logging/log_backend_uart.h b/include/logging/log_backend_uart.h new file mode 100644 index 00000000000..116abbd4650 --- /dev/null +++ b/include/logging/log_backend_uart.h @@ -0,0 +1,31 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef LOG_BACKEND_UART_H +#define LOG_BACKEND_UART_H + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +extern const struct log_backend_api log_backend_uart_api; + +/** + * @brief UART backend definition + * + * @param _name Name of the instance. + */ +#define LOG_BACKEND_UART_DEFINE(_name) \ + LOG_BACKEND_DEFINE(_name, log_backend_uart_api) + +#ifdef __cplusplus +} +#endif + +void log_backend_uart_init(void); + +#endif /* LOG_BACKEND_UART_H */ diff --git a/include/logging/log_core.h b/include/logging/log_core.h new file mode 100644 index 00000000000..5db11487268 --- /dev/null +++ b/include/logging/log_core.h @@ -0,0 +1,262 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef LOG_FRONTEND_H +#define LOG_FRONTEND_H + +#include +#include +#include + +#ifdef __cplusplus +extern "C" { +#endif + +#ifndef CONFIG_LOG_DEFAULT_LEVEL +#define CONFIG_LOG_DEFAULT_LEVEL LOG_LEVEL_NONE +#endif + +#ifndef CONFIG_LOG_MAX_LEVEL +#define CONFIG_LOG_MAX_LEVEL LOG_LEVEL_NONE +#endif + +#define CONFIG_LOG_DOMAIN_ID 0 + +#define LOG_LEVEL_BITS 3 + +/** @brief Macro for returning local level value if defined or default. + * + * Check @ref IS_ENABLED macro for detailed explanation of the trick. + */ +#define _LOG_RESOLVED_LEVEL(_level, _default) \ + _LOG_RESOLVED_LEVEL1(_level, _default) + +#define _LOG_RESOLVED_LEVEL1(_level, _default) \ + __LOG_RESOLVED_LEVEL2(_LOG_XXXX##_level, _level, _default) + +#define _LOG_XXXX0 _LOG_YYYY, +#define _LOG_XXXX1 _LOG_YYYY, +#define _LOG_XXXX2 _LOG_YYYY, +#define _LOG_XXXX3 _LOG_YYYY, +#define _LOG_XXXX4 _LOG_YYYY, + +#define __LOG_RESOLVED_LEVEL2(one_or_two_args, _level, _default) \ + __LOG_RESOLVED_LEVEL3(one_or_two_args _level, _default) + +#define __LOG_RESOLVED_LEVEL3(ignore_this, val, ...) val + +/******************************************************************************/ +/****************** Internal macros for log frontend **************************/ +/******************************************************************************/ +#define _LOG_INTERNAL_X(N, ...) UTIL_CAT(_LOG_INTERNAL_, N)(__VA_ARGS__) + +#define __LOG_INTERNAL(_src_level, ...) \ + _LOG_INTERNAL_X(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \ + _src_level, __VA_ARGS__) + +#define _LOG_INTERNAL_0(_src_level, _str) \ + log_0(_str, _src_level) + +#define _LOG_INTERNAL_1(_src_level, _str, _arg0) \ + log_1(_str, (u32_t)_arg0, _src_level) + +#define _LOG_INTERNAL_2(_src_level, _str, _arg0, _arg1) \ + log_2(_str, (u32_t)_arg0, (u32_t)_arg1, _src_level) + +#define _LOG_INTERNAL_3(_src_level, _str, _arg0, _arg1, _arg2) \ + log_3(_str, (u32_t)_arg0, (u32_t)_arg1, (u32_t)_arg2, _src_level) + +#define __LOG_ARG_CAST(_x) (u32_t)(_x), + +#define __LOG_ARGUMENTS(...) MACRO_MAP(__LOG_ARG_CAST, __VA_ARGS__) + +#define _LOG_INTERNAL_LONG(_src_level, _str, ...) \ + do { \ + u32_t args[] = {__LOG_ARGUMENTS(__VA_ARGS__)}; \ + log_n(_str, args, ARRAY_SIZE(args), _src_level); \ + } while (0) + +#define _LOG_INTERNAL_4(_src_level, _str, ...) \ + _LOG_INTERNAL_LONG(_src_level, _str, __VA_ARGS__) + +#define _LOG_INTERNAL_5(_src_level, _str, ...) \ + _LOG_INTERNAL_LONG(_src_level, _str, __VA_ARGS__) + +#define _LOG_INTERNAL_6(_src_level, _str, ...) \ + _LOG_INTERNAL_LONG(_src_level, _str, __VA_ARGS__) + +#define _LOG_INTERNAL_7(_src_level, _str, ...) \ + _LOG_INTERNAL_LONG(_src_level, _str, __VA_ARGS__) + +#define _LOG_LEVEL_CHECK(_level, _check_level, _default_level) \ + (_level <= _LOG_RESOLVED_LEVEL(_check_level, _default_level)) + +#define _LOG_CONST_LEVEL_CHECK(_level) \ + (IS_ENABLED(CONFIG_LOG) && \ + ( \ + _LOG_LEVEL_CHECK(_level, CONFIG_LOG_OVERRIDE_LEVEL, LOG_LEVEL_NONE) \ + || \ + (!IS_ENABLED(CONFIG_LOG_OVERRIDE_LEVEL) && \ + _LOG_LEVEL_CHECK(_level, LOG_LEVEL, CONFIG_LOG_DEFAULT_LEVEL) && \ + (_level <= CONFIG_LOG_MAX_LEVEL) \ + ) \ + )) + +/******************************************************************************/ +/****************** Macros for standard logging *******************************/ +/******************************************************************************/ +#define __LOG(_level, _id, _filter, ...) \ + do { \ + if (_LOG_CONST_LEVEL_CHECK(_level) && \ + (_level <= LOG_RUNTIME_FILTER(_filter))) { \ + struct log_msg_ids src_level = { \ + .level = _level, \ + .source_id = _id, \ + .domain_id = CONFIG_LOG_DOMAIN_ID \ + }; \ + log_printf_arg_checker(__VA_ARGS__); \ + __LOG_INTERNAL(src_level, __VA_ARGS__); \ + } \ + } while (0) + +#define _LOG(_level, ...) \ + __LOG(_level, \ + LOG_CURRENT_MODULE_ID(), \ + &LOG_ITEM_DYNAMIC_DATA(LOG_MODULE_NAME), \ + __VA_ARGS__) + +#define _LOG_INSTANCE(_level, _inst, ...) \ + __LOG(_level, \ + IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + LOG_DYNAMIC_ID_GET(_inst) : \ + LOG_CONST_ID_GET(_inst), \ + _inst, \ + __VA_ARGS__) + + +/******************************************************************************/ +/****************** Macros for hexdump logging ********************************/ +/******************************************************************************/ +#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length) \ + do { \ + if (_LOG_CONST_LEVEL_CHECK(_level) && \ + (_level <= LOG_RUNTIME_FILTER(_filter))) { \ + struct log_msg_ids src_level = { \ + .level = _level, \ + .source_id = _id, \ + .domain_id = CONFIG_LOG_DOMAIN_ID \ + }; \ + log_hexdump(_data, _length, src_level); \ + } \ + } while (0) + +#define _LOG_HEXDUMP(_level, _data, _length) \ + __LOG_HEXDUMP(_level, \ + LOG_CURRENT_MODULE_ID(), \ + &LOG_ITEM_DYNAMIC_DATA(LOG_MODULE_NAME), \ + _data, _length) + +#define _LOG_HEXDUMP_INSTANCE(_level, _inst, _data, _length) \ + __LOG_HEXDUMP(_level, \ + IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + LOG_DYNAMIC_ID_GET(_inst) : \ + LOG_CONST_ID_GET(_inst), \ + _inst, \ + _data, \ + _length) + +/** @brief Dummy function to trigger log messages arguments type checking. */ +static inline __printf_like(1, 2) +void log_printf_arg_checker(const char *fmt, ...) +{ + +} + +/** @brief Standard log with no arguments. + * + * @param str String. + * @param src_level Log identification. + */ +void log_0(const char *str, struct log_msg_ids src_level); + +/** @brief Standard log with one argument. + * + * @param str String. + * @param arg1 First argument. + * @param src_level Log identification. + */ +void log_1(const char *str, + u32_t arg1, + struct log_msg_ids src_level); + +/** @brief Standard log with two arguments. + * + * @param str String. + * @param arg1 First argument. + * @param arg2 Second argument. + * @param src_level Log identification. + */ +void log_2(const char *str, + u32_t arg1, + u32_t arg2, + struct log_msg_ids src_level); + +/** @brief Standard log with three arguments. + * + * @param str String. + * @param arg1 First argument. + * @param arg2 Second argument. + * @param arg3 Third argument. + * @param src_level Log identification. + */ +void log_3(const char *str, + u32_t arg1, + u32_t arg2, + u32_t arg3, + struct log_msg_ids src_level); + +/** @brief Standard log with arguments list. + * + * @param str String. + * @param args Array with arguments. + * @param narg Number of arguments in the array. + * @param src_level Log identification. + */ +void log_n(const char *str, + u32_t *args, + u32_t narg, + struct log_msg_ids src_level); + +/** @brief Hexdump log. + * + * @param data Data. + * @param length Data length. + * @param src_level Log identification. + */ +void log_hexdump(const u8_t *data, + u32_t length, + struct log_msg_ids src_level); + +/** @brief Format and put string into log message. + * + * @param fmt String to format. + * @param ap Variable list of arguments. + * + * @return Number of bytes processed. + */ +int log_printk(const char *fmt, va_list ap); + +/** + * @brief Writes a generic log message to the log. + * + * @note This function is intended to be used when porting other log systems. + */ +void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap); + +#ifdef __cplusplus +} +#endif + +#endif /* LOG_FRONTEND_H */ diff --git a/include/logging/log_ctrl.h b/include/logging/log_ctrl.h new file mode 100644 index 00000000000..25892016fec --- /dev/null +++ b/include/logging/log_ctrl.h @@ -0,0 +1,140 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef LOG_CTRL_H +#define LOG_CTRL_H + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +typedef u32_t (*timestamp_get_t)(void); + +/** + * @brief Function for initializing logger core. + * + * @return 0 on success or error. + */ +int log_init(void); + +/** + * @brief Function for providing timestamp function. + * + * @param timestamp_getter Timestamp function. + * @param freq Timestamping frequency. + * + * @return 0 on success or error. + */ +int log_set_timestamp_func(timestamp_get_t timestamp_getter, u32_t freq); + +/** + * @brief Switch logger subsystem to panic mode. + * + * @details On panic logger subsystem informs all backends about panic mode. + * Backends must switch to blocking mode or halt. All pending logs + * 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); + +/** + * @brief Process one pending log message. + * + * @param bypass If true message is released without being processed. + * + * @retval true There is more messages pending to be processed. + * @retval false No messages pending. + */ +bool log_process(bool bypass); + +/** @brief Get number of independent logger sources (modules and instances) + * + * @param domain_id Domain ID. + * + * @return Number of sources. + */ +u32_t log_src_cnt_get(u32_t domain_id); + + +/** @brief Get name of the source (module or instance). + * + * @param domain_id Domain ID. + * @param src_id Source ID. + * + * @return Source name. + */ +const char *log_source_name_get(u32_t domain_id, u32_t src_id); + +/** @brief Get name of the domain. + * + * @param domain_id Domain ID. + * + * @return Domain name. + */ +const char *log_domain_name_get(u32_t domain_id); + +/** + * @brief Get source filter for the provided backend. + * + * @param backend Backend instance. + * @param domain_id ID of the domain. + * @param src_id Source (module or instance) ID. + * @param runtime True for runtime filter or false for compiled in. + * + * @return Severity level. + */ +u32_t log_filter_get(struct log_backend const *const backend, + u32_t domain_id, u32_t src_id, bool runtime); + +/** + * @brief Set filter on given source for the provided backend. + * + * @param backend Backend instance. + * @param domain_id ID of the domain. + * @param src_id Source (module or instance) ID. + * @param level Severity level. + */ +void log_filter_set(struct log_backend const *const backend, + u32_t domain_id, + u32_t src_id, + u32_t level); + +/** + * + * @brief Enable backend with initial maximum filtering level. + * + * @param backend Backend instance. + * @param ctx User csontext. + * @param level Severity level. + */ +void log_backend_enable(struct log_backend const *const backend, + void *ctx, + u32_t level); + +/** + * + * @brief Disable backend. + * + * @param backend Backend instance. + */ +void log_backend_disable(struct log_backend const *const backend); + +#if defined(CONFIG_LOG) && CONFIG_LOG +#define LOG_INIT() log_init() +#define LOG_PANIC() log_panic() +#define LOG_PROCESS() log_process(false) +#else +#define LOG_INIT() 0 +#define LOG_PANIC() /* Empty */ +#define LOG_PROCESS() false +#endif + +#ifdef __cplusplus +} +#endif + +#endif /* LOG_CTRL_H */ diff --git a/include/logging/log_instance.h b/include/logging/log_instance.h new file mode 100644 index 00000000000..7c51a47ee3b --- /dev/null +++ b/include/logging/log_instance.h @@ -0,0 +1,273 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef LOG_INSTANCE_H +#define LOG_INSTANCE_H + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** @brief Constant data associated with the source of log messages. */ +struct log_source_const_data { + const char *name; + u8_t level; +}; + +/** @brief Dynamic data associated with the source of log messages. */ +struct log_source_dynamic_data { + u32_t filters; +}; + +extern struct log_source_const_data __log_const_start[0]; +extern struct log_source_const_data __log_const_end[0]; + + +/** @brief Creates name of variable and section for constant log data. + * + * @param _name Name. + */ +#define LOG_ITEM_CONST_DATA(_name) UTIL_CAT(log_const_, _name) + +/** @brief Get name of the log source. + * + * @param source_id Source ID. + * @return Name. + */ +static inline const char *log_name_get(u32_t source_id) +{ + return __log_const_start[source_id].name; +} + +/** @brief Get compiled level of the log source. + * + * @param source_id Source ID. + * @return Level. + */ +static inline u8_t log_compiled_level_get(u32_t source_id) +{ + return __log_const_start[source_id].level; +} + +/** @brief Get index of the log source based on the address of the constant data + * associated with the source. + * + * @param data Address of the constant data. + * + * @return Source ID. + */ +static inline u32_t log_const_source_id( + const struct log_source_const_data *data) +{ + return ((void *)data - (void *)__log_const_start)/ + sizeof(struct log_source_const_data); +} + +/** @brief Get number of registered sources. */ +static inline u32_t log_sources_count(void) +{ + return log_const_source_id(__log_const_end); +} + +extern struct log_source_dynamic_data __log_dynamic_start[0]; +extern struct log_source_dynamic_data __log_dynamic_end[0]; + +/** @brief Creates name of variable and section for runtime log data. + * + * @param _name Name. + */ +#define LOG_ITEM_DYNAMIC_DATA(_name) UTIL_CAT(log_dynamic_, _name) + +#define LOG_INSTANCE_DYNAMIC_DATA(_module_name, _inst) \ + LOG_ITEM_DYNAMIC_DATA(LOG_INSTANCE_FULL_NAME(_module_name, _inst)) + +/** @brief Get pointer to the filter set of the log source. + * + * @param source_id Source ID. + * + * @return Pointer to the filter set. + */ +static inline u32_t *log_dynamic_filters_get(u32_t source_id) +{ + return &__log_dynamic_start[source_id].filters; +} + +/** @brief Get index of the log source based on the address of the dynamic data + * associated with the source. + * + * @param data Address of the dynamic data. + * + * @return Source ID. + */ +static inline u32_t log_dynamic_source_id(struct log_source_dynamic_data *data) +{ + return ((void *)data - (void *)__log_dynamic_start)/ + sizeof(struct log_source_dynamic_data); +} + +/** + * @def LOG_CONST_ID_GET + * @brief Macro for getting ID of the element of the section. + * + * @param _addr Address of the element. + */ +/** + * @def LOG_CURRENT_MODULE_ID + * @brief Macro for getting ID of current module. + */ +#ifdef CONFIG_LOG +#define LOG_CONST_ID_GET(_addr) \ + log_const_source_id((const struct log_source_const_data *)_addr) +#define LOG_CURRENT_MODULE_ID() \ + log_const_source_id(&LOG_ITEM_CONST_DATA(LOG_MODULE_NAME)) +#else +#define LOG_CONST_ID_GET(_addr) 0 +#define LOG_CURRENT_MODULE_ID() 0 +#endif + +/** @brief Macro for getting ID of the element of the section. + * + * @param _addr Address of the element. + */ +#if CONFIG_LOG +#define LOG_DYNAMIC_ID_GET(_addr) \ + log_dynamic_source_id((struct log_source_dynamic_data *)_addr) +#else +#define LOG_DYNAMIC_ID_GET(_addr) 0 +#endif + +/******************************************************************************/ +/****************** Filtering macros ******************************************/ +/******************************************************************************/ + +/** @brief Filter slot size. */ +#define LOG_FILTER_SLOT_SIZE LOG_LEVEL_BITS + +/** @brief Number of slots in one word. */ +#define LOG_FILTERS_NUM_OF_SLOTS (32 / LOG_FILTER_SLOT_SIZE) + +/** @brief Slot mask. */ +#define LOG_FILTER_SLOT_MASK ((1 << LOG_FILTER_SLOT_SIZE) - 1) + +/** @brief Bit offset of a slot. + * + * @param _id Slot ID. + */ +#define LOG_FILTER_SLOT_SHIFT(_id) (LOG_FILTER_SLOT_SIZE * (_id)) + +#define LOG_FILTER_SLOT_GET(_filters, _id) \ + ((*(_filters) >> LOG_FILTER_SLOT_SHIFT(_id)) & LOG_FILTER_SLOT_MASK) + +#define LOG_FILTER_SLOT_SET(_filters, _id, _filter) \ + do { \ + *(_filters) &= ~(LOG_FILTER_SLOT_MASK << \ + LOG_FILTER_SLOT_SHIFT(_id)); \ + *(_filters) |= ((_filter) & LOG_FILTER_SLOT_MASK) << \ + LOG_FILTER_SLOT_SHIFT(_id); \ + } while (0) + +#define LOG_FILTER_AGGR_SLOT_IDX 0 + +#define LOG_FILTER_AGGR_SLOT_GET(_filters) \ + LOG_FILTER_SLOT_GET(_filters, LOG_FILTER_AGGR_SLOT_IDX) + +#define LOG_FILTER_FIRST_BACKEND_SLOT_IDX 1 + +#if CONFIG_LOG_RUNTIME_FILTERING +#define LOG_RUNTIME_FILTER(_filter) \ + LOG_FILTER_SLOT_GET(&(_filter)->filters, LOG_FILTER_AGGR_SLOT_IDX) +#else +#define LOG_RUNTIME_FILTER(_filter) LOG_LEVEL_DBG +#endif + +#define _LOG_CONST_ITEM_REGISTER(_name, _str_name, _level) \ + const struct log_source_const_data LOG_ITEM_CONST_DATA(_name) \ + __attribute__ ((section("." STRINGIFY(LOG_ITEM_CONST_DATA(_name))))) \ + __attribute__((used)) = { \ + .name = _str_name, \ + .level = (_level), \ + } + +#if CONFIG_LOG_RUNTIME_FILTERING +#define _LOG_DYNAMIC_ITEM_REGISTER(_name) \ + struct log_source_dynamic_data LOG_ITEM_DYNAMIC_DATA(_name) \ + __attribute__ ((section("." STRINGIFY(LOG_ITEM_DYNAMIC_DATA(_name))))) \ + __attribute__((used)) +#else +#define _LOG_DYNAMIC_ITEM_REGISTER(_name) /* empty */ +#endif + +/** @def LOG_INSTANCE_PTR_DECLARE + * @brief Macro for declaring a logger instance pointer in the module structure. + */ + +/** @def LOG_INSTANCE_REGISTER + * @brief Macro for registering instance for logging with independent filtering. + * + * Module instance provides filtering of logs on instance level instead of + * module level. + */ + +/** @def LOG_INSTANCE_PTR_INIT + * @brief Macro for initializing a pointer to the logger instance. + */ + +/** @} */ + +#ifdef CONFIG_LOG + +#define LOG_INSTANCE_FULL_NAME(_module_name, _inst_name) \ + UTIL_CAT(_module_name, UTIL_CAT(_, _inst_name)) + +#if CONFIG_LOG_RUNTIME_FILTERING +#define LOG_INSTANCE_PTR_DECLARE(_name) \ + struct log_source_dynamic_data *_name + +#define LOG_INSTANCE_REGISTER(_module_name, _inst_name, _level) \ + _LOG_CONST_ITEM_REGISTER( \ + LOG_INSTANCE_FULL_NAME(_module_name, _inst_name), \ + STRINGIFY(_module_name._inst_name), \ + _level); \ + struct log_source_dynamic_data LOG_INSTANCE_DYNAMIC_DATA( \ + _module_name, _inst_name) \ + __attribute__ ((section("." STRINGIFY( \ + LOG_INSTANCE_DYNAMIC_DATA(_module_name, \ + _inst_name) \ + ) \ + ))) __attribute__((used)) + +#define LOG_INSTANCE_PTR_INIT(_name, _module_name, _inst_name) \ + ._name = &LOG_ITEM_DYNAMIC_DATA( \ + LOG_INSTANCE_FULL_NAME(_module_name, _inst_name)), + +#else /* CONFIG_LOG_RUNTIME_FILTERING */ +#define LOG_INSTANCE_PTR_DECLARE(_name) \ + const struct log_source_const_data *_name + +#define LOG_INSTANCE_REGISTER(_module_name, _inst_name, _level) \ + _LOG_CONST_ITEM_REGISTER( \ + LOG_INSTANCE_FULL_NAME(_module_name, _inst_name), \ + STRINGIFY(_module_name._inst_name), \ + _level) + + +#define LOG_INSTANCE_PTR_INIT(_name, _module_name, _inst_name) \ + ._name = &LOG_ITEM_CONST_DATA( \ + LOG_INSTANCE_FULL_NAME(_module_name, _inst_name)), + +#endif /* CONFIG_LOG_RUNTIME_FILTERING */ +#else /* CONFIG_LOG */ +#define LOG_INSTANCE_PTR_DECLARE(_name) /* empty */ +#define LOG_INSTANCE_REGISTER(_module_name, _inst_name, _level) /* empty */ +#define LOG_INSTANCE_PTR_INIT(_name, _module_name, _inst_name) /* empty */ +#endif + +#ifdef __cplusplus +} +#endif + +#endif /* LOG_INSTANCE_H */ diff --git a/include/logging/log_msg.h b/include/logging/log_msg.h new file mode 100644 index 00000000000..58056931821 --- /dev/null +++ b/include/logging/log_msg.h @@ -0,0 +1,524 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef LOG_MSG_H +#define LOG_MSG_H + +#include +#include +#include +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** @brief Maximum number of arguments in the standard log entry. */ +#define LOG_MAX_NARGS 6 + +/** @brief Number of arguments in the log entry which fits in one chunk.*/ +#define LOG_MSG_NARGS_SINGLE_CHUNK 3 + +/** @brief Number of arguments in the head of extended standard log message..*/ +#define LOG_MSG_NARGS_HEAD_CHUNK (LOG_MSG_NARGS_SINGLE_CHUNK - 1) + +/** @brief Maximal amount of bytes in the hexdump entry which fits in one chunk. + */ +#define LOG_MSG_HEXDUMP_BYTES_SINGLE_CHUNK \ + (LOG_MSG_NARGS_SINGLE_CHUNK * sizeof(u32_t)) + +/** @brief Number of bytes in the first chunk of hexdump message if message + * consists of more than one chunk. + */ +#define LOG_MSG_HEXDUMP_BYTES_HEAD_CHUNK \ + (LOG_MSG_HEXDUMP_BYTES_SINGLE_CHUNK - sizeof(void *)) + +/** @brief Number of bytes that can be stored in chunks following head chunk + * in hexdump log message. + */ +#define HEXDUMP_BYTES_CONT_MSG \ + (sizeof(struct log_msg) - sizeof(void *)) + +#define ARGS_CONT_MSG (HEXDUMP_BYTES_CONT_MSG / sizeof(u32_t)) + +/** @brief Flag indicating standard log message. */ +#define LOG_MSG_TYPE_STD 0 + +/** @brief Flag indicating hexdump log message. */ +#define LOG_MSG_TYPE_HEXDUMP 1 + +/** @brief Common part of log message header. */ +#define COMMON_PARAM_HDR() \ + u16_t type : 1; \ + u16_t ext : 1 + +/** @brief Number of bits used for storing length of hexdump log message. */ +#define LOG_MSG_HEXDUMP_LENGTH_BITS 13 + +/** @brief Maximum length of log hexdump message. */ +#define LOG_MSG_HEXDUMP_MAX_LENGTH ((1 << LOG_MSG_HEXDUMP_LENGTH_BITS) - 1) + +/** @brief Part of log message header identifying source and level. */ +struct log_msg_ids { + u16_t level : 3; /*!< Severity. */ + u16_t domain_id : 3; /*!< Originating domain. */ + u16_t source_id : 10; /*!< Source ID. */ +}; + +_Static_assert(sizeof(struct log_msg_ids) == sizeof(u16_t), + "Structure must fit in 2 bytes"); + +/** Part of log message header common to standard and hexdump log message. */ +struct log_msg_generic_hdr { + COMMON_PARAM_HDR(); + u16_t reserved : 14; +}; + +_Static_assert(sizeof(struct log_msg_generic_hdr) == sizeof(u16_t), + "Structure must fit in 2 bytes"); + +/** Part of log message header specific to standard log message. */ +struct log_msg_std_hdr { + COMMON_PARAM_HDR(); + u16_t reserved : 10; + u16_t nargs : 4; +}; + +_Static_assert(sizeof(struct log_msg_std_hdr) == sizeof(u16_t), + "Structure must fit in 2 bytes"); + +/** Part of log message header specific to hexdump log message. */ +struct log_msg_hexdump_hdr { + COMMON_PARAM_HDR(); + u16_t raw_string : 1; + u16_t length : LOG_MSG_HEXDUMP_LENGTH_BITS; +}; + +_Static_assert(sizeof(struct log_msg_hexdump_hdr) == sizeof(u16_t), + "Structure must fit in 2 bytes"); + +/** Log message header structure */ +struct log_msg_hdr { + atomic_t ref_cnt; /*!< Reference counter for tracking message users. */ + union { + struct log_msg_generic_hdr generic; + struct log_msg_std_hdr std; + struct log_msg_hexdump_hdr hexdump; + u16_t raw; + } params; + struct log_msg_ids ids; /*!< Identification part of the message.*/ + u32_t timestamp; /*!< Timestamp. */ +}; + +/** @brief Data part of head of standard log message. */ +struct log_msg_std_head_data { + const char *str; + u32_t args[LOG_MSG_NARGS_SINGLE_CHUNK]; +}; + +/** @brief Data part of head of extended standard log message. + * + * @details When message is extended, head of the message contains also a + * pointer to the next chunk thus data part is reduced. + */ +struct log_msg_std_ext_head_data { + const char *str; + u32_t args[LOG_MSG_NARGS_HEAD_CHUNK]; +}; + +/** @brief Data part of log message. */ +union log_msg_head_data { + struct log_msg_std_head_data std; + u8_t bytes[LOG_MSG_HEXDUMP_BYTES_SINGLE_CHUNK]; +}; + +/** @brief Data part of extended log message. */ +struct log_msg_ext_head_data { + struct log_msg_cont *next; + union { + struct log_msg_std_ext_head_data std; + u8_t bytes[LOG_MSG_HEXDUMP_BYTES_HEAD_CHUNK]; + } data; +}; + +/** @brief Log message structure. */ +struct log_msg { + struct log_msg *next; /*!< Used by logger core list.*/ + struct log_msg_hdr hdr; /*!< Message header. */ + + union { + union log_msg_head_data data; + struct log_msg_ext_head_data ext; + } data; /*!< Message data. */ +}; + +_Static_assert(sizeof(union log_msg_head_data) == + sizeof(struct log_msg_ext_head_data), + "Structure must be same size"); + +/** @brief Chunks following message head when message is extended. */ +struct log_msg_cont { + struct log_msg_cont *next; /*!< Pointer to the next chunk. */ + union { + u32_t args[ARGS_CONT_MSG]; + u8_t bytes[HEXDUMP_BYTES_CONT_MSG]; + } data; +}; + +/** @brief Log message */ +union log_msg_chunk { + struct log_msg head; + struct log_msg_cont cont; +}; + +extern struct k_mem_slab log_msg_pool; + +/** @brief Function for indicating that message is in use. + * + * @details Message can be used (read) by multiple users. Internal reference + * counter is atomically increased. See @ref log_msg_put. + * + * @param msg Message. + */ +void log_msg_get(struct log_msg *msg); + +/** @brief Function for indicating that message is no longer in use. + * + * @details Internal reference counter is atomically decreased. If reference + * counter equals 0 message is freed. + * + * @param msg Message. + */ +void log_msg_put(struct log_msg *msg); + +/** @brief Get domain ID of the message. + * + * @param msg Message + * + * @return Domain ID. + */ +static inline u32_t log_msg_domain_id_get(struct log_msg *msg) +{ + return msg->hdr.ids.domain_id; +} + +/** @brief Get source ID (module or instance) of the message. + * + * @param msg Message + * + * @return Source ID. + */ +static inline u32_t log_msg_source_id_get(struct log_msg *msg) +{ + return msg->hdr.ids.source_id; +} + +/** @brief Get severity level of the message. + * + * @param msg Message + * + * @return Severity message. + */ +static inline u32_t log_msg_level_get(struct log_msg *msg) +{ + return msg->hdr.ids.level; +} + +/** @brief Get timestamp of the message. + * + * @param msg Message + * + * @return Timestamp value. + */ +static inline u32_t log_msg_timestamp_get(struct log_msg *msg) +{ + return msg->hdr.timestamp; +} + +/** @brief Check if message is a raw string (see CONFIG_LOG_PRINTK). + * + * @param msg Message + * + * @retval true Message contains raw string. + * @retval false Message does not contain raw string. + */ +static inline bool log_msg_is_raw_string(struct log_msg *msg) +{ + return (msg->hdr.params.generic.type == LOG_MSG_TYPE_HEXDUMP) && + (msg->hdr.params.hexdump.raw_string == 1); +} + + +/** @brief Check if message is of standard type. + * + * @param msg Message + * + * @retval true Standard message. + * @retval false Hexdump message. + */ +static inline bool log_msg_is_std(struct log_msg *msg) +{ + return (msg->hdr.params.generic.type == LOG_MSG_TYPE_STD); +} + +/** @brief Returns number of arguments in standard log message. + * + * @param msg Standard log message. + * + * @return Number of arguments. + */ +u32_t log_msg_nargs_get(struct log_msg *msg); + +/** @brief Gets argument from standard log message. + * + * @param msg Standard log message. + * @param arg_idx Argument index. + * + * @return Argument value. + */ +u32_t log_msg_arg_get(struct log_msg *msg, u32_t arg_idx); + + +/** @brief Gets pointer to the unformatted string from standard log message. + * + * @param msg Standard log message. + * + * @return Pointer to the string. + */ +const char *log_msg_str_get(struct log_msg *msg); + +/** @brief Allocates chunks for hexdump message and copies the data. + * + * @details Function resets header and sets following fields: + * - message type + * - length + * + * @note Allocation and partial filling is combined for performance reasons. + * + * @param data Data. + * @param length Data length. + * + * @return Pointer to allocated head of the message or NULL + */ +struct log_msg *log_msg_hexdump_create(const u8_t *data, u32_t length); + +/** @brief Put data into hexdump log message. + * + * @param[in] msg Message. + * @param[in] data Data to be copied. + * @param[in, out] length Input: requested amount. Output: actual amount. + * @param[in] offset Offset. + */ +void log_msg_hexdump_data_put(struct log_msg *msg, + u8_t *data, + size_t *length, + size_t offset); + +/** @brief Get data from hexdump log message. + * + * @param[in] msg Message. + * @param[in] data Buffer for data. + * @param[in, out] length Input: requested amount. Output: actual amount. + * @param[in] offset Offset. + */ +void log_msg_hexdump_data_get(struct log_msg *msg, + u8_t *data, + size_t *length, + size_t offset); + +union log_msg_chunk *log_msg_no_space_handle(void); + +static inline union log_msg_chunk *log_msg_chunk_alloc(void) +{ + union log_msg_chunk *msg = NULL; + int err = k_mem_slab_alloc(&log_msg_pool, (void **)&msg, K_NO_WAIT); + + if (err != 0) { + msg = log_msg_no_space_handle(); + } + + return msg; +} + +/** @brief Allocate chunk for standard log message. + * + * @return Allocated chunk of NULL. + */ +static inline struct log_msg *_log_msg_std_alloc(void) +{ + struct log_msg *msg = (struct log_msg *)log_msg_chunk_alloc(); + + if (msg) { + /* all fields reset to 0, reference counter to 1 */ + msg->hdr.ref_cnt = 1; + msg->hdr.params.raw = 0; + msg->hdr.params.std.type = LOG_MSG_TYPE_STD; + } + + return msg; +} + +/** @brief Allocate chunk for extended standard log message. + * + * @details Extended standard log message is used when number of arguments + * exceeds capacity of one chunk. Extended message consists of two + * chunks. Such approach is taken to optimize memory usage and + * performance assuming that log messages with more arguments + * (@ref LOG_MSG_NARGS_SINGLE_CHUNK) are less common. + * + * @return Allocated chunk of NULL. + */ +static inline struct log_msg *_log_msg_ext_std_alloc(void) +{ + struct log_msg_cont *cont; + struct log_msg *msg = _log_msg_std_alloc(); + + if (msg != NULL) { + cont = (struct log_msg_cont *)log_msg_chunk_alloc(); + if (cont == NULL) { + k_mem_slab_free(&log_msg_pool, (void **)&msg); + return NULL; + } + + msg->hdr.params.generic.ext = 1; + msg->data.ext.next = cont; + cont->next = NULL; + } + + return msg; +} + +/** @brief Create standard log message with no arguments. + * + * @details Function resets header and sets following fields: + * - message type + * - string pointer + * + * @return Pointer to allocated head of the message or NULL. + */ +static inline struct log_msg *log_msg_create_0(const char *str) +{ + struct log_msg *msg = _log_msg_std_alloc(); + + if (msg != NULL) { + msg->data.data.std.str = str; + } + + return msg; +} + +/** @brief Create standard log message with one argument. + * + * @details Function resets header and sets following fields: + * - message type + * - string pointer + * - number of arguments + * - argument + * + * @param str String. + * @param arg1 Argument. + * + * @return Pointer to allocated head of the message or NULL. + */ +static inline struct log_msg *log_msg_create_1(const char *str, + u32_t arg1) +{ + struct log_msg *msg = _log_msg_std_alloc(); + + if (msg != NULL) { + msg->hdr.params.std.nargs = 1; + msg->data.data.std.str = str; + msg->data.data.std.args[0] = arg1; + } + + return msg; +} + +/** @brief Create standard log message with two arguments. + * + * @details Function resets header and sets following fields: + * - message type + * - string pointer + * - number of arguments + * - arguments + * + * @param str String. + * @param arg1 Argument 1. + * @param arg2 Argument 2. + * + * @return Pointer to allocated head of the message or NULL. + */ +static inline struct log_msg *log_msg_create_2(const char *str, + u32_t arg1, + u32_t arg2) +{ + struct log_msg *msg = _log_msg_std_alloc(); + + if (msg != NULL) { + msg->hdr.params.std.nargs = 2; + msg->data.data.std.str = str; + msg->data.data.std.args[0] = arg1; + msg->data.data.std.args[1] = arg2; + } + + return msg; +} + +/** @brief Create standard log message with three arguments. + * + * @details Function resets header and sets following fields: + * - message type + * - string pointer + * - number of arguments + * - arguments + * + * @param str String. + * @param arg1 Argument 1. + * @param arg2 Argument 2. + * @param arg3 Argument 3. + * + * @return Pointer to allocated head of the message or NULL. + */ +static inline struct log_msg *log_msg_create_3(const char *str, + u32_t arg1, + u32_t arg2, + u32_t arg3) +{ + struct log_msg *msg = _log_msg_std_alloc(); + + if (msg != NULL) { + msg->hdr.params.std.nargs = 3; + msg->data.data.std.str = str; + msg->data.data.std.args[0] = arg1; + msg->data.data.std.args[1] = arg2; + msg->data.data.std.args[2] = arg3; + } + + return msg; +} + +/** @brief Create standard log message with variable number of arguments. + * + * @details Function resets header and sets following fields: + * - message type + * - string pointer + * - number of arguments + * - arguments + * + * @param str String. + * @param args Array with arguments. + * @param nargs Number of arguments. + * + * @return Pointer to allocated head of the message or NULL. + */ +struct log_msg *log_msg_create_n(const char *str, + u32_t *args, + u32_t nargs); + +#ifdef __cplusplus +} +#endif + +#endif /* LOG_MSG_H */ diff --git a/include/logging/log_output.h b/include/logging/log_output.h new file mode 100644 index 00000000000..a6efa731319 --- /dev/null +++ b/include/logging/log_output.h @@ -0,0 +1,65 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef LOG_OUTPUT_H +#define LOG_OUTPUT_H + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** @brief Flag forcing ANSI escape code colors, red (errors), yellow + * (warnings). + */ +#define LOG_OUTPUT_FLAG_COLORS (1 << 0) + +/** @brief Flag forcing timestamp formatting. */ +#define LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP (1 << 1) + +/** + * @brief Prototype of the function processing output data. + * + * @param data Data. + * @param length Data length. + * @param ctx User context. + * + * @return Number of bytes processed. + */ +typedef int (*log_output_func_t)(u8_t *data, size_t length, void *ctx); + +struct log_output_ctx { + log_output_func_t func; + u8_t *data; + size_t length; + size_t offset; + void *ctx; +}; + +/** @brief Function for processing log messages to readable strings. + * + * Function is using provided context with the buffer and output function to + * process formatted string and output the data. + * + * @param msg Log message. + * @param ctx Context. + * @param flags Optional flags. + */ +void log_output_msg_process(struct log_msg *msg, + struct log_output_ctx *ctx, + u32_t flags); + +/** @brief Function for setting timestamp frequency. + * + * @param freq Frequency in Hz. + */ +void log_output_timestamp_freq_set(u32_t freq); + +#ifdef __cplusplus +} +#endif + +#endif /* LOG_OUTPUT_H */ diff --git a/include/misc/util.h b/include/misc/util.h index 2ba6b5f8517..b84421717ee 100644 --- a/include/misc/util.h +++ b/include/misc/util.h @@ -325,4 +325,80 @@ static inline s64_t arithmetic_shift_right(s64_t value, u8_t shift) */ #define UTIL_LISTIFY(LEN, F, F_ARG) UTIL_EVAL(UTIL_REPEAT(LEN, F, F_ARG)) +/**@brief Implementation details for NUM_VAR_ARGS */ +#define NUM_VA_ARGS_LESS_1_IMPL( \ + _ignored, \ + _0, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, \ + _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, \ + _21, _22, _23, _24, _25, _26, _27, _28, _29, _30, \ + _31, _32, _33, _34, _35, _36, _37, _38, _39, _40, \ + _41, _42, _43, _44, _45, _46, _47, _48, _49, _50, \ + _51, _52, _53, _54, _55, _56, _57, _58, _59, _60, \ + _61, _62, N, ...) N + +/**@brief Macro to get the number of arguments in a call variadic macro call. + * First argument is not counted. + * + * param[in] ... List of arguments + * + * @retval Number of variadic arguments in the argument list + */ +#define NUM_VA_ARGS_LESS_1(...) \ + NUM_VA_ARGS_LESS_1_IMPL(__VA_ARGS__, 63, 62, 61, \ + 60, 59, 58, 57, 56, 55, 54, 53, 52, 51, \ + 50, 49, 48, 47, 46, 45, 44, 43, 42, 41, \ + 40, 39, 38, 37, 36, 35, 34, 33, 32, 31, \ + 30, 29, 28, 27, 26, 25, 24, 23, 22, 21, \ + 20, 19, 18, 17, 16, 15, 14, 13, 12, 11, \ + 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0, ~) + +/** + * @brief Mapping macro + * + * Macro that process all arguments using given macro + * + * @param ... Macro name to be used for argument processing followed by + * arguments to process. Macro should have following + * form: MACRO(argument). + * + * @return All arguments processed by given macro + */ +#define MACRO_MAP(...) MACRO_MAP_(__VA_ARGS__) +#define MACRO_MAP_(...) \ + /* To make sure it works also for 2 arguments in total */ \ + MACRO_MAP_N(NUM_VA_ARGS_LESS_1(__VA_ARGS__), __VA_ARGS__) + +/** + * @brief Mapping N arguments macro + * + * Macro similar to @ref MACRO_MAP but maps exact number of arguments. + * If there is more arguments given, the rest would be ignored. + * + * @param N Number of arguments to map + * @param ... Macro name to be used for argument processing followed by + * arguments to process. Macro should have following + * form: MACRO(argument). + * + * @return Selected number of arguments processed by given macro + */ +#define MACRO_MAP_N(N, ...) MACRO_MAP_N_(N, __VA_ARGS__) +#define MACRO_MAP_N_(N, ...) UTIL_CAT(MACRO_MAP_, N)(__VA_ARGS__,) + +#define MACRO_MAP_0(...) +#define MACRO_MAP_1(macro, a, ...) macro(a) +#define MACRO_MAP_2(macro, a, ...) macro(a)MACRO_MAP_1(macro, __VA_ARGS__,) +#define MACRO_MAP_3(macro, a, ...) macro(a)MACRO_MAP_2(macro, __VA_ARGS__,) +#define MACRO_MAP_4(macro, a, ...) macro(a)MACRO_MAP_3(macro, __VA_ARGS__,) +#define MACRO_MAP_5(macro, a, ...) macro(a)MACRO_MAP_4(macro, __VA_ARGS__,) +#define MACRO_MAP_6(macro, a, ...) macro(a)MACRO_MAP_5(macro, __VA_ARGS__,) +#define MACRO_MAP_7(macro, a, ...) macro(a)MACRO_MAP_6(macro, __VA_ARGS__,) +#define MACRO_MAP_8(macro, a, ...) macro(a)MACRO_MAP_7(macro, __VA_ARGS__,) +#define MACRO_MAP_9(macro, a, ...) macro(a)MACRO_MAP_8(macro, __VA_ARGS__,) +#define MACRO_MAP_10(macro, a, ...) macro(a)MACRO_MAP_9(macro, __VA_ARGS__,) +#define MACRO_MAP_11(macro, a, ...) macro(a)MACRO_MAP_10(macro, __VA_ARGS__,) +#define MACRO_MAP_12(macro, a, ...) macro(a)MACRO_MAP_11(macro, __VA_ARGS__,) +#define MACRO_MAP_13(macro, a, ...) macro(a)MACRO_MAP_12(macro, __VA_ARGS__,) +#define MACRO_MAP_14(macro, a, ...) macro(a)MACRO_MAP_13(macro, __VA_ARGS__,) +#define MACRO_MAP_15(macro, a, ...) macro(a)MACRO_MAP_14(macro, __VA_ARGS__,) + #endif /* _UTIL__H_ */ diff --git a/misc/printk.c b/misc/printk.c index e9ee67dba7b..f0d45e77be6 100644 --- a/misc/printk.c +++ b/misc/printk.c @@ -18,6 +18,7 @@ #include #include #include +#include typedef int (*out_func_t)(int c, void *ctx); @@ -338,7 +339,12 @@ int printk(const char *fmt, ...) va_list ap; va_start(ap, fmt); - ret = vprintk(fmt, ap); + + if (IS_ENABLED(CONFIG_LOG_PRINTK)) { + ret = log_printk(fmt, ap); + } else { + ret = vprintk(fmt, ap); + } va_end(ap); return ret; diff --git a/subsys/logging/CMakeLists.txt b/subsys/logging/CMakeLists.txt index 7f86ad5bc26..3df7e06c080 100644 --- a/subsys/logging/CMakeLists.txt +++ b/subsys/logging/CMakeLists.txt @@ -4,4 +4,18 @@ zephyr_sources_ifdef( event_logger.c kernel_event_logger.c ) + zephyr_sources_ifdef(CONFIG_SYS_LOG_BACKEND_NET sys_log_net.c) + +zephyr_sources_ifdef( + CONFIG_LOG + log_list.c + log_core.c + log_msg.c + log_output.c + ) + +zephyr_sources_ifdef( + CONFIG_LOG_BACKEND_UART + log_backend_uart.c + ) diff --git a/subsys/logging/Kconfig b/subsys/logging/Kconfig index 3b5e5354b31..87f9450e8f2 100644 --- a/subsys/logging/Kconfig +++ b/subsys/logging/Kconfig @@ -120,5 +120,135 @@ config SYS_LOG_BACKEND_NET_MAX_BUF_SIZE endif +config LOG + bool "Enable Logger" + help + Global switch for the logger, when turned off log calls will not be + compiled in. + +if LOG +config LOG_RUNTIME_FILTERING + bool "Enable runtime reconfiguration of the logger" + help + Allow runtime configuration of maximal, independent severity + level for instance. + +choice + prompt "Log full strategy" + +config LOG_MODE_OVERFLOW + bool "Oldest logs are discarded" + +config LOG_MODE_NO_OVERFLOW + bool "New logs are dropped" + +endchoice + +config LOG_DEFAULT_LEVEL + int "Default log level" + default 3 + range 0 4 + help + Sets log level for modules which don't specify it explicitly. When + set to 0 it means log will not be activated for those modules. + Levels are: + + - 0 OFF, do not write by default + - 1 ERROR, default to only write LOG_LEVEL_ERR + - 2 WARNING, default to write LOG_LEVEL_WRN + - 3 INFO, default to write LOG_LEVEL_INFO + - 4 DEBUG, default to write LOG_LEVEL_DBG + +config LOG_OVERRIDE_LEVEL + int "Override lowest log level" + default 0 + range 0 4 + help + Forces a minimum log level for all modules. Modules use their + specified level if it is greater than this option, otherwise they use + the level specified by this option instead of their default or + whatever was manually set. + Levels are: + + - 0 OFF, do not override + - 1 ERROR, override to write LOG_LEVEL_ERR + - 2 WARNING, override to write LOG_LEVEL_WRN + - 3 INFO, override to write LOG_LEVEL_INFO + - 4 DEBUG, override to write LOG_LEVEL_DBG + +config LOG_MAX_LEVEL + int "Maximal log level compiled in the system" + default 4 + range 0 4 + help + Forces a maximal log level for all modules. Modules saturates their + specified level if it is greater than this option, otherwise they use + the level specified by this option instead of their default or + whatever was manually set. + Levels are: + + - 0 OFF, logging is turned off + - 1 ERROR, maximal level set to LOG_LEVEL_ERR + - 2 WARNING, maximal level set to LOG_LEVEL_WRN + - 3 INFO, maximal level set to LOG_LEVEL_INFO + - 4 DEBUG, maximal level set to LOG_LEVEL_DBG + +config LOG_PRINTK + bool "Enable processing of printk messages." + help + LOG_PRINTK messages are formatten in place and logged unconditionally. + +config LOG_PRINTK_MAX_STRING_LENGTH + int "Maximum string length supported by LOG_PRINTK" + depends on LOG_PRINTK + default 128 + help + Array is allocated on the stack. + +config LOG_INPLACE_PROCESS + bool "Enable in place processing" + help + When enabled log is processed in the context of the call. It impacts + performance of the system since time consuming operations are performed in + the context of the log entry (e.g. high priority interrupt). When enabled + LOG_BUFFER_SIZE can be reduced. Logger backends must support exclusive + access to work flawlessly in that mode because one log operation can be + interrupted by another one in higher priority context. + +config LOG_BUFFER_SIZE + int "Number of bytes dedicated for the logger internal buffer." + default 1024 + range 128 65536 + help + Number of bytes dedicated for the logger internal buffer. + +config LOG_DOMAIN_ID + int "Domain ID" + default 0 + range 0 7 + help + In multicore system each application/core must have unique domain ID. + +config LOG_BACKEND_UART + bool "Enable UART backend" + depends on UART_CONSOLE + default y + help + When enabled backend is using UART to output logs. + +config LOG_BACKEND_UART_SHOW_COLOR + bool "Enable colors in the UART backend" + depends on LOG_BACKEND_UART + default y + help + When enabled UART backend prints errors in red and warning in yellow. + +config LOG_BACKEND_UART_FORMAT_TIMESTAMP + bool "Enable timestamp formatting in the UART backend" + depends on LOG_BACKEND_UART + default y + help + When enabled timestamp is formatted to hh:mm:ss:ms,us. +endif endmenu diff --git a/subsys/logging/log_backend_uart.c b/subsys/logging/log_backend_uart.c new file mode 100644 index 00000000000..4d379675b13 --- /dev/null +++ b/subsys/logging/log_backend_uart.c @@ -0,0 +1,67 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#include +#include +#include +#include +#include +#include + +int char_out(u8_t *data, size_t length, void *ctx) +{ + struct device *dev = (struct device *)ctx; + + for (size_t i = 0; i < length; i++) { + uart_poll_out(dev, data[i]); + } + + return length; +} + +static u8_t buf; + +static struct log_output_ctx ctx = { + .func = char_out, + .data = &buf, + .length = 1, + .offset = 0 +}; + +static void put(const struct log_backend *const backend, + struct log_msg *msg) +{ + log_msg_get(msg); + + u32_t flags = 0; + + if (IS_ENABLED(CONFIG_LOG_BACKEND_UART_SHOW_COLOR)) { + flags |= LOG_OUTPUT_FLAG_COLORS; + } + + if (IS_ENABLED(CONFIG_LOG_BACKEND_UART_FORMAT_TIMESTAMP)) { + flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP; + } + + log_output_msg_process(msg, &ctx, flags); + + log_msg_put(msg); + +} + +void log_backend_uart_init(void) +{ + ctx.ctx = device_get_binding(CONFIG_UART_CONSOLE_ON_DEV_NAME); +} + +static void panic(struct log_backend const *const backend) +{ + +} + +const struct log_backend_api log_backend_uart_api = { + .put = put, + .panic = panic, +}; diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c new file mode 100644 index 00000000000..fc508a46e3e --- /dev/null +++ b/subsys/logging/log_core.c @@ -0,0 +1,395 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#include +#include "log_list.h" +#include +#include +#include +#include +#include +#include +#include + +#ifndef CONFIG_LOG_PRINTK_MAX_STRING_LENGTH +#define CONFIG_LOG_PRINTK_MAX_STRING_LENGTH 1 +#endif + +#ifdef CONFIG_LOG_BACKEND_UART +#include +LOG_BACKEND_UART_DEFINE(log_backend_uart); +#endif + +static struct log_list_t list; +static bool panic_mode; +static bool initialized; + +static timestamp_get_t timestamp_func; + +static inline void msg_finalize(struct log_msg *msg, + struct log_msg_ids src_level) +{ + msg->hdr.ids = src_level; + msg->hdr.timestamp = timestamp_func(); + unsigned int key = irq_lock(); + + log_list_add_tail(&list, msg); + + irq_unlock(key); + + if (IS_ENABLED(CONFIG_LOG_INPLACE_PROCESS) || panic_mode) { + (void)log_process(false); + } +} + +void log_0(const char *str, struct log_msg_ids src_level) +{ + struct log_msg *msg = log_msg_create_0(str); + + if (msg == NULL) { + return; + } + msg_finalize(msg, src_level); +} + +void log_1(const char *str, + u32_t arg0, + struct log_msg_ids src_level) +{ + 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, + u32_t arg0, + u32_t arg1, + struct log_msg_ids src_level) +{ + 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, + u32_t arg0, + u32_t arg1, + u32_t arg2, + struct log_msg_ids src_level) +{ + 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, + u32_t *args, + u32_t narg, + struct log_msg_ids src_level) +{ + struct log_msg *msg = log_msg_create_n(str, args, narg); + + if (msg == NULL) { + return; + } + + msg_finalize(msg, src_level); +} + +void log_hexdump(const u8_t *data, + u32_t length, + struct log_msg_ids src_level) +{ + struct log_msg *msg = log_msg_hexdump_create(data, length); + + if (msg == NULL) { + return; + } + + msg_finalize(msg, src_level); +} + +int log_printk(const char *fmt, va_list ap) +{ + if (IS_ENABLED(CONFIG_LOG_PRINTK)) { + u8_t formatted_str[CONFIG_LOG_PRINTK_MAX_STRING_LENGTH]; + struct log_msg_ids empty_id = { 0 }; + struct log_msg *msg; + int length; + + if (!initialized) { + log_init(); + } + + length = vsnprintf(formatted_str, + sizeof(formatted_str), fmt, ap); + + length = (length > sizeof(formatted_str)) ? + sizeof(formatted_str) : length; + + msg = log_msg_hexdump_create(formatted_str, length); + if (!msg) { + return 0; + } + + msg->hdr.params.hexdump.raw_string = 1; + msg_finalize(msg, empty_id); + + return length; + } else { + return 0; + } +} + +void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap) +{ + u32_t args[LOG_MAX_NARGS]; + + for (int i = 0; i < LOG_MAX_NARGS; i++) { + args[i] = va_arg(ap, u32_t); + } + + /* Assume maximum amount of parameters. Determining exact number would + * require string analysis. + */ + log_n(fmt, args, LOG_MAX_NARGS, src_level); +} + +static u32_t timestamp_get(void) +{ + return k_cycle_get_32(); +} + +int log_init(void) +{ + assert(log_backend_count_get() < LOG_FILTERS_NUM_OF_SLOTS); + + /* Set default timestamp. */ + timestamp_func = timestamp_get; + log_output_timestamp_freq_set(CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC); + + if (!initialized) { + log_list_init(&list); + + /* Assign ids to backends. */ + for (int i = 0; i < log_backend_count_get(); i++) { + log_backend_id_set(log_backend_get(i), + i + LOG_FILTER_FIRST_BACKEND_SLOT_IDX); + } + + panic_mode = false; + initialized = true; + } + +#ifdef CONFIG_LOG_BACKEND_UART + log_backend_uart_init(); + log_backend_enable(&log_backend_uart, + NULL, + CONFIG_LOG_DEFAULT_LEVEL); +#endif + return 0; +} + +int log_set_timestamp_func(timestamp_get_t timestamp_getter, u32_t freq) +{ + if (!timestamp_getter) { + return -EINVAL; + } + + timestamp_func = timestamp_getter; + log_output_timestamp_freq_set(freq); + + return 0; +} + +void log_panic(void) +{ + struct log_backend const *backend; + + 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); + } + } + + panic_mode = true; + + /* Flush */ + while (log_process(false) == true) { + } +} + +static bool msg_filter_check(struct log_backend const *backend, + struct log_msg *msg) +{ + u32_t backend_level; + u32_t msg_level; + + backend_level = log_filter_get(backend, + log_msg_domain_id_get(msg), + log_msg_source_id_get(msg), + true /*enum RUNTIME, COMPILETIME*/); + msg_level = log_msg_level_get(msg); + + return (msg_level <= backend_level); +} + +static void msg_process(struct log_msg *msg, bool bypass) +{ + struct log_backend const *backend; + + if (!bypass) { + 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)) { + log_backend_put(backend, msg); + } + } + } + + log_msg_put(msg); +} + +bool log_process(bool bypass) +{ + struct log_msg *msg; + + unsigned int key = irq_lock(); + + msg = log_list_head_get(&list); + irq_unlock(key); + + if (msg != NULL) { + msg_process(msg, bypass); + } + + return (log_list_head_peek(&list) != NULL); +} + +u32_t log_src_cnt_get(u32_t domain_id) +{ + return log_sources_count(); +} + +const char *log_source_name_get(u32_t domain_id, u32_t src_id) +{ + assert(src_id < log_sources_count()); + + return log_name_get(src_id); +} + +static u32_t max_filter_get(u32_t filters) +{ + u32_t max_filter = LOG_LEVEL_NONE; + int first_slot = LOG_FILTER_FIRST_BACKEND_SLOT_IDX; + int i; + + for (i = first_slot; i < LOG_FILTERS_NUM_OF_SLOTS; i++) { + u32_t tmp_filter = LOG_FILTER_SLOT_GET(&filters, i); + + if (tmp_filter > max_filter) { + max_filter = tmp_filter; + } + } + + return max_filter; +} + +void log_filter_set(struct log_backend const *const backend, + u32_t domain_id, + u32_t src_id, + u32_t level) +{ + assert(src_id < log_sources_count()); + + if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) { + u32_t new_aggr_filter; + + u32_t *filters = log_dynamic_filters_get(src_id); + + if (backend == NULL) { + struct log_backend const *backend; + + for (int i = 0; i < log_backend_count_get(); i++) { + backend = log_backend_get(i); + log_filter_set(backend, domain_id, + src_id, level); + } + } else { + LOG_FILTER_SLOT_SET(filters, + log_backend_id_get(backend), + level); + + /* Once current backend filter is updated recalculate + * aggregated maximal level + */ + new_aggr_filter = max_filter_get(*filters); + + LOG_FILTER_SLOT_SET(filters, + LOG_FILTER_AGGR_SLOT_IDX, + new_aggr_filter); + } + } +} + +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); + + } + } +} + +void log_backend_enable(struct log_backend const *const backend, + void *ctx, + u32_t level) +{ + log_backend_activate(backend, ctx); + backend_filter_set(backend, level); +} + +void log_backend_disable(struct log_backend const *const backend) +{ + log_backend_deactivate(backend); + backend_filter_set(backend, LOG_LEVEL_NONE); +} + +u32_t log_filter_get(struct log_backend const *const backend, + u32_t domain_id, + u32_t src_id, + bool runtime) +{ + assert(src_id < log_sources_count()); + + if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) && runtime) { + u32_t *filters = log_dynamic_filters_get(src_id); + + return LOG_FILTER_SLOT_GET(filters, + log_backend_id_get(backend)); + } else { + return log_compiled_level_get(src_id); + } +} diff --git a/subsys/logging/log_list.c b/subsys/logging/log_list.c new file mode 100644 index 00000000000..d6c800c6886 --- /dev/null +++ b/subsys/logging/log_list.c @@ -0,0 +1,41 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "log_list.h" + +void log_list_init(struct log_list_t *list) +{ + list->tail = NULL; + list->head = NULL; +} + +void log_list_add_tail(struct log_list_t *list, struct log_msg *msg) +{ + if (list->head == NULL) { + list->head = msg; + } else { + list->tail->next = msg; + } + + list->tail = msg; + msg->next = NULL; +} + +struct log_msg *log_list_head_peek(struct log_list_t *list) +{ + return list->head; +} + +struct log_msg *log_list_head_get(struct log_list_t *list) +{ + struct log_msg *msg = list->head; + + if (list->head != NULL) { + list->head = list->head->next; + } + + return msg; +} diff --git a/subsys/logging/log_list.h b/subsys/logging/log_list.h new file mode 100644 index 00000000000..b2c7c38c5ac --- /dev/null +++ b/subsys/logging/log_list.h @@ -0,0 +1,55 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef LOG_LIST_H_ +#define LOG_LIST_H_ + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** @brief List instance structure. */ +struct log_list_t { + struct log_msg *head; + struct log_msg *tail; +}; + +/** @brief Initialize log list instance. + * + * @param list List instance. + */ +void log_list_init(struct log_list_t *list); + +/** @brief Add item to the tail of the list. + * + * @param list List instance. + * @param msg Message. + * + */ +void log_list_add_tail(struct log_list_t *list, struct log_msg *msg); + +/** @brief Remove item from the head of the list. + * + * @param list List instance. + * + * @return Message. + */ +struct log_msg *log_list_head_get(struct log_list_t *list); + +/** @brief Peek item from the head of the list. + * + * @param list List instance. + * + * @return Message. + */ +struct log_msg *log_list_head_peek(struct log_list_t *list); + +#ifdef __cplusplus +} +#endif + +#endif /* LOG_LIST_H_ */ diff --git a/subsys/logging/log_msg.c b/subsys/logging/log_msg.c new file mode 100644 index 00000000000..f4ca7bc4b17 --- /dev/null +++ b/subsys/logging/log_msg.c @@ -0,0 +1,279 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#include +#include +#include +#include + +#define MSG_SIZE sizeof(union log_msg_chunk) +#define NUM_OF_MSGS (CONFIG_LOG_BUFFER_SIZE / MSG_SIZE) + +K_MEM_SLAB_DEFINE(log_msg_pool, MSG_SIZE, NUM_OF_MSGS, sizeof(u32_t)); + +void log_msg_get(struct log_msg *msg) +{ + atomic_inc(&msg->hdr.ref_cnt); +} + +static void cont_free(struct log_msg_cont *cont) +{ + struct log_msg_cont *next; + + while (cont != NULL) { + next = cont->next; + k_mem_slab_free(&log_msg_pool, (void **)&cont); + cont = next; + } +} + +static void msg_free(struct log_msg *msg) +{ + if (msg->hdr.params.generic.ext == 1) { + cont_free(msg->data.ext.next); + } + k_mem_slab_free(&log_msg_pool, (void **)&msg); +} + +union log_msg_chunk *log_msg_no_space_handle(void) +{ + union log_msg_chunk *msg = NULL; + bool more; + int err; + + if (IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) { + do { + more = log_process(true); + err = k_mem_slab_alloc(&log_msg_pool, + (void **)&msg, + K_NO_WAIT); + } while ((err != 0) && more); + } + return msg; + +} +void log_msg_put(struct log_msg *msg) +{ + atomic_dec(&msg->hdr.ref_cnt); + + if (msg->hdr.ref_cnt == 0) { + msg_free(msg); + } +} + +u32_t log_msg_nargs_get(struct log_msg *msg) +{ + return msg->hdr.params.std.nargs; +} + +u32_t log_msg_arg_get(struct log_msg *msg, u32_t arg_idx) +{ + u32_t arg; + + if (msg->hdr.params.std.nargs <= LOG_MSG_NARGS_SINGLE_CHUNK) { + arg = msg->data.data.std.args[arg_idx]; + } else { + if (arg_idx < LOG_MSG_NARGS_HEAD_CHUNK) { + arg = msg->data.ext.data.std.args[arg_idx]; + } else { + arg_idx -= LOG_MSG_NARGS_HEAD_CHUNK; + arg = msg->data.ext.next->data.args[arg_idx]; + } + } + + return arg; +} + +const char *log_msg_str_get(struct log_msg *msg) +{ + if (log_msg_nargs_get(msg) <= LOG_MSG_NARGS_SINGLE_CHUNK) { + return msg->data.data.std.str; + } else { + return msg->data.ext.data.std.str; + } +} + +struct log_msg *log_msg_create_n(const char *str, + u32_t *args, + u32_t nargs) +{ + struct log_msg *msg; + + if (nargs <= LOG_MSG_NARGS_SINGLE_CHUNK) { + msg = _log_msg_std_alloc(); + + if (msg != NULL) { + msg->hdr.params.std.nargs = nargs; + msg->data.data.std.str = str; + memcpy(msg->data.data.std.args, args, nargs); + } + } else { + msg = _log_msg_ext_std_alloc(); + + if (msg != NULL) { + msg->hdr.params.std.nargs = nargs; + msg->data.ext.data.std.str = str; + /* Direct assignment will be faster than memcpy. */ + msg->data.ext.data.std.args[0] = args[0]; + msg->data.ext.data.std.args[1] = args[1]; + memcpy(msg->data.ext.next->data.args, + &args[LOG_MSG_NARGS_HEAD_CHUNK], + (nargs - LOG_MSG_NARGS_HEAD_CHUNK)*sizeof(u32_t)); + } + } + + return msg; +} + +struct log_msg *log_msg_hexdump_create(const u8_t *data, u32_t length) +{ + struct log_msg_cont **prev_cont; + struct log_msg_cont *cont; + struct log_msg *msg; + u32_t chunk_length; + + /* Saturate length. */ + length = (length > LOG_MSG_HEXDUMP_MAX_LENGTH) ? + LOG_MSG_HEXDUMP_MAX_LENGTH : length; + + msg = (struct log_msg *)log_msg_chunk_alloc(); + if (!msg) { + return NULL; + } + + /* all fields reset to 0, reference counter to 1 */ + msg->hdr.ref_cnt = 1; + msg->hdr.params.hexdump.type = LOG_MSG_TYPE_HEXDUMP; + msg->hdr.params.hexdump.raw_string = 0; + msg->hdr.params.hexdump.length = length; + + + if (length > LOG_MSG_HEXDUMP_BYTES_SINGLE_CHUNK) { + memcpy(msg->data.ext.data.bytes, + data, + LOG_MSG_HEXDUMP_BYTES_HEAD_CHUNK); + + msg->hdr.params.generic.ext = 1; + msg->data.ext.next = NULL; + + data += LOG_MSG_HEXDUMP_BYTES_HEAD_CHUNK; + length -= LOG_MSG_HEXDUMP_BYTES_HEAD_CHUNK; + } else { + memcpy(msg->data.data.bytes, data, length); + msg->hdr.params.generic.ext = 0; + length = 0; + } + + prev_cont = &msg->data.ext.next; + + while (length > 0) { + cont = (struct log_msg_cont *)log_msg_chunk_alloc(); + if (!cont) { + msg_free(msg); + return NULL; + } + + *prev_cont = cont; + cont->next = NULL; + prev_cont = &cont->next; + + chunk_length = (length > HEXDUMP_BYTES_CONT_MSG) ? + HEXDUMP_BYTES_CONT_MSG : length; + + memcpy(cont->data.bytes, data, chunk_length); + data += chunk_length; + length -= chunk_length; + } + + return msg; +} + +static void log_msg_hexdump_data_op(struct log_msg *msg, + u8_t *data, + size_t *length, + size_t offset, + bool put_op) +{ + u32_t available_len = msg->hdr.params.hexdump.length; + struct log_msg_cont *cont = NULL; + u8_t *head_data; + u32_t chunk_len; + u32_t req_len; + u32_t cpy_len; + + if (offset >= available_len) { + *length = 0; + return; + } + + if ((offset + *length) > available_len) { + *length = available_len - offset; + } + + req_len = *length; + + if (available_len > LOG_MSG_HEXDUMP_BYTES_SINGLE_CHUNK) { + chunk_len = LOG_MSG_HEXDUMP_BYTES_HEAD_CHUNK; + head_data = msg->data.ext.data.bytes; + cont = msg->data.ext.next; + } else { + head_data = msg->data.data.bytes; + chunk_len = available_len; + + } + + if (offset < chunk_len) { + cpy_len = req_len > chunk_len ? chunk_len : req_len; + + if (put_op) { + memcpy(&head_data[offset], data, cpy_len); + } else { + memcpy(data, &head_data[offset], cpy_len); + } + + req_len -= cpy_len; + data += cpy_len; + } else { + offset -= chunk_len; + chunk_len = HEXDUMP_BYTES_CONT_MSG; + + while (offset > chunk_len) { + cont = cont->next; + offset -= chunk_len; + } + } + + while (req_len > 0) { + chunk_len = HEXDUMP_BYTES_CONT_MSG - offset; + cpy_len = req_len > chunk_len ? chunk_len : req_len; + + if (put_op) { + memcpy(&cont->data.bytes[offset], data, cpy_len); + } else { + memcpy(data, &cont->data.bytes[offset], cpy_len); + } + + offset = 0; + cont = cont->next; + req_len -= cpy_len; + data += cpy_len; + } +} + +void log_msg_hexdump_data_put(struct log_msg *msg, + u8_t *data, + size_t *length, + size_t offset) +{ + log_msg_hexdump_data_op(msg, data, length, offset, true); +} + +void log_msg_hexdump_data_get(struct log_msg *msg, + u8_t *data, + size_t *length, + size_t offset) +{ + log_msg_hexdump_data_op(msg, data, length, offset, false); +} diff --git a/subsys/logging/log_output.c b/subsys/logging/log_output.c new file mode 100644 index 00000000000..4c2ba0d8339 --- /dev/null +++ b/subsys/logging/log_output.c @@ -0,0 +1,351 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include + +#define HEXDUMP_BYTES_IN_LINE 8 + +#define LOG_COLOR_CODE_DEFAULT "\x1B[0m" +#define LOG_COLOR_CODE_BLACK "\x1B[1;30m" +#define LOG_COLOR_CODE_RED "\x1B[1;31m" +#define LOG_COLOR_CODE_GREEN "\x1B[1;32m" +#define LOG_COLOR_CODE_YELLOW "\x1B[1;33m" +#define LOG_COLOR_CODE_BLUE "\x1B[1;34m" +#define LOG_COLOR_CODE_MAGENTA "\x1B[1;35m" +#define LOG_COLOR_CODE_CYAN "\x1B[1;36m" +#define LOG_COLOR_CODE_WHITE "\x1B[1;37m" + +static const char *const severity[] = { + NULL, + "err", + "warn", + "info", + "dbg" +}; + +static const char *const colors[] = { + NULL, + LOG_COLOR_CODE_RED, /* err */ + LOG_COLOR_CODE_YELLOW, /* warn */ + NULL, /* info */ + NULL /* dbg */ +}; + +static u32_t freq; +static u32_t timestamp_div; + +typedef int (*out_func_t)(int c, void *ctx); + +extern int _prf(int (*func)(), void *dest, char *format, va_list vargs); +extern void _vprintk(out_func_t out, void *ctx, const char *fmt, va_list ap); + +static int out_func(int c, void *ctx) +{ + struct log_output_ctx *out_ctx = (struct log_output_ctx *)ctx; + + out_ctx->data[out_ctx->offset] = (u8_t)c; + out_ctx->offset++; + + if (out_ctx->offset == out_ctx->length) { + out_ctx->func(out_ctx->data, out_ctx->length, out_ctx->ctx); + out_ctx->offset = 0; + } + + return 0; +} + +static int print(struct log_output_ctx *ctx, const char *fmt, ...) +{ + va_list args; + int length = 0; + + va_start(args, fmt); +#ifndef CONFIG_NEWLIB_LIBC + length = _prf(out_func, ctx, (char *)fmt, args); +#else + _vprintk(out_func, ctx, fmt, args); +#endif + va_end(args); + + return length; +} + +static void flush(struct log_output_ctx *ctx) +{ + ctx->func(ctx->data, ctx->offset, ctx->ctx); +} + +static int timestamp_print(struct log_msg *msg, + struct log_output_ctx *ctx, + bool format) +{ + int length; + u32_t timestamp = log_msg_timestamp_get(msg); + + if (!format) { + length = print(ctx, "[%08lu] ", timestamp); + } else { + u32_t reminder; + u32_t seconds; + u32_t hours; + u32_t mins; + u32_t ms; + u32_t us; + + timestamp /= timestamp_div; + seconds = timestamp / freq; + hours = seconds / 3600; + seconds -= hours * 3600; + mins = seconds / 60; + seconds -= mins * 60; + + reminder = timestamp % freq; + ms = (reminder * 1000) / freq; + us = (1000 * (1000 * reminder - (ms * freq))) / freq; + + length = print(ctx, "[%02d:%02d:%02d.%03d,%03d] ", + hours, mins, seconds, ms, us); + } + + return length; +} + +static void color_print(struct log_msg *msg, + struct log_output_ctx *ctx, + bool color, + bool start) +{ + if (color) { + u32_t level = log_msg_level_get(msg); + + if (colors[level] != NULL) { + const char *color = start ? + colors[level] : LOG_COLOR_CODE_DEFAULT; + + print(ctx, "%s", color); + } + } +} + +static void color_prefix(struct log_msg *msg, + struct log_output_ctx *ctx, + bool color) +{ + color_print(msg, ctx, color, true); +} + +static void color_postfix(struct log_msg *msg, + struct log_output_ctx *ctx, + bool color) +{ + color_print(msg, ctx, color, false); +} + + +static int ids_print(struct log_msg *msg, + struct log_output_ctx *ctx) +{ + u32_t domain_id = log_msg_domain_id_get(msg); + u32_t source_id = log_msg_source_id_get(msg); + u32_t level = log_msg_level_get(msg); + + return print(ctx, "<%s> %s: ", severity[level], + log_source_name_get(domain_id, source_id)); +} + +static void newline_print(struct log_output_ctx *ctx) +{ + print(ctx, "\r\n"); +} + +static void std_print(struct log_msg *msg, + struct log_output_ctx *ctx) +{ + const char *str = log_msg_str_get(msg); + + switch (log_msg_nargs_get(msg)) { + case 0: + print(ctx, str); + break; + case 1: + print(ctx, str, log_msg_arg_get(msg, 0)); + break; + case 2: + print(ctx, str, + log_msg_arg_get(msg, 0), + log_msg_arg_get(msg, 1)); + break; + case 3: + print(ctx, str, + log_msg_arg_get(msg, 0), + log_msg_arg_get(msg, 1), + log_msg_arg_get(msg, 2)); + break; + case 4: + print(ctx, str, + log_msg_arg_get(msg, 0), + log_msg_arg_get(msg, 1), + log_msg_arg_get(msg, 2), + log_msg_arg_get(msg, 3)); + break; + case 5: + print(ctx, str, + log_msg_arg_get(msg, 0), + log_msg_arg_get(msg, 1), + log_msg_arg_get(msg, 2), + log_msg_arg_get(msg, 3), + log_msg_arg_get(msg, 4)); + break; + case 6: + print(ctx, str, + log_msg_arg_get(msg, 0), + log_msg_arg_get(msg, 1), + log_msg_arg_get(msg, 2), + log_msg_arg_get(msg, 3), + log_msg_arg_get(msg, 4), + log_msg_arg_get(msg, 5)); + break; + } +} + +static u32_t hexdump_line_print(struct log_msg *msg, + struct log_output_ctx *ctx, + int prefix_offset, + u32_t offset) +{ + u8_t buf[HEXDUMP_BYTES_IN_LINE]; + size_t length = sizeof(buf); + + log_msg_hexdump_data_get(msg, buf, &length, offset); + + if (length > 0) { + if (offset > 0) { + newline_print(ctx); + for (int i = 0; i < prefix_offset; i++) { + print(ctx, " "); + } + } + + for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) { + if (i < length) { + print(ctx, " %02x", buf[i]); + } else { + print(ctx, " "); + } + } + + print(ctx, "|"); + + for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) { + if (i < length) { + char c = (char)buf[i]; + + print(ctx, "%c", isprint((int)c) ? c : '.'); + } else { + print(ctx, " "); + } + } + } + + return length; +} + +static void hexdump_print(struct log_msg *msg, + struct log_output_ctx *ctx, + int prefix_offset) +{ + u32_t offset = 0; + u32_t length; + + do { + length = hexdump_line_print(msg, ctx, prefix_offset, offset); + + if (length < HEXDUMP_BYTES_IN_LINE) { + break; + } + + offset += length; + } while (1); +} + +static void raw_string_print(struct log_msg *msg, + struct log_output_ctx *ctx) +{ + size_t offset = 0; + size_t length; + + while (length > 0) { + length = ctx->length; + log_msg_hexdump_data_get(msg, ctx->data, &length, offset); + offset += length; + ctx->func(ctx->data, length, ctx->ctx); + } + + print(ctx, "\r"); +} + +static int prefix_print(struct log_msg *msg, + struct log_output_ctx *ctx, + u32_t flags) +{ + int length = 0; + + if (!log_msg_is_raw_string(msg)) { + bool stamp_format = flags & LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP; + bool colors_on = flags & LOG_OUTPUT_FLAG_COLORS; + + length += timestamp_print(msg, ctx, stamp_format); + color_prefix(msg, ctx, colors_on); + length += ids_print(msg, ctx); + } + + return length; +} + +static void postfix_print(struct log_msg *msg, + struct log_output_ctx *ctx, + u32_t flags) +{ + if (!log_msg_is_raw_string(msg)) { + color_postfix(msg, ctx, (flags & LOG_OUTPUT_FLAG_COLORS)); + newline_print(ctx); + } +} + +void log_output_msg_process(struct log_msg *msg, + struct log_output_ctx *ctx, + u32_t flags) +{ + int prefix_offset = prefix_print(msg, ctx, flags); + + if (log_msg_is_std(msg)) { + std_print(msg, ctx); + } else if (log_msg_is_raw_string(msg)) { + raw_string_print(msg, ctx); + } else { + hexdump_print(msg, ctx, prefix_offset); + } + + postfix_print(msg, ctx, flags); + + flush(ctx); +} + +void log_output_timestamp_freq_set(u32_t frequency) +{ + timestamp_div = 1; + /* There is no point to have frequency higher than 1MHz (ns are not + * printed) and too high frequency leads to overflows in calculations. + */ + while (frequency > 1000000) { + frequency /= 2; + timestamp_div *= 2; + } + + freq = frequency; +}