diff --git a/doc/reference/logging/index.rst b/doc/reference/logging/index.rst index 1be1bd2b287..e869e03afa1 100644 --- a/doc/reference/logging/index.rst +++ b/doc/reference/logging/index.rst @@ -137,6 +137,9 @@ which handles log processing. message pool. Single message capable of storing standard log with up to 3 arguments or hexdump message with 12 bytes of data take 32 bytes. +:option:`CONFIG_LOG_DETECT_MISSED_STRDUP`: Enable detection of missed transient +strings handling. + :option:`CONFIG_LOG_STRDUP_MAX_STRING`: Longest string that can be duplicated using log_strdup(). @@ -418,6 +421,7 @@ copies of strings. The buffer size and count is configurable (see :option:`CONFIG_LOG_STRDUP_MAX_STRING` and :option:`CONFIG_LOG_STRDUP_BUF_COUNT`). + If a string argument is transient, the user must call cpp:func:`log_strdup` to duplicate the passed string into a buffer from the pool. See the examples below. If a strdup buffer cannot be allocated, a warning message is logged and an error @@ -431,6 +435,12 @@ increased. Buffers are freed together with the log message. LOG_INF("logging transient string: %s", log_strdup(local_str)); local_str[0] = '\0'; /* String can be modified, logger will use duplicate." +When :option:`CONFIG_LOG_DETECT_MISSED_STRDUP` is enabled logger will scan +each log message and report if string format specifier is found and string +address is not in read only memory section or does not belong to memory pool +dedicated to string duplicates. It indictes that cpp:func:`log_strdup` is +missing in a call to log a message, such as ``LOG_INF``. + Logger backends =============== diff --git a/include/logging/log_core.h b/include/logging/log_core.h index 669e2f6d733..6837776955b 100644 --- a/include/logging/log_core.h +++ b/include/logging/log_core.h @@ -535,7 +535,7 @@ void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap); * * @return True if address within the pool, false otherwise. */ -bool log_is_strdup(void *buf); +bool log_is_strdup(const void *buf); /** @brief Free allocated buffer. * diff --git a/subsys/logging/Kconfig b/subsys/logging/Kconfig index d178f364141..d47a09546be 100644 --- a/subsys/logging/Kconfig +++ b/subsys/logging/Kconfig @@ -175,6 +175,17 @@ config LOG_BUFFER_SIZE help Number of bytes dedicated for the logger internal buffer. +config LOG_DETECT_MISSED_STRDUP + bool "Detect missed handling of transient strings" + default y if !LOG_IMMEDIATE + help + If enabled, logger will assert and log error message is it detects + that string format specifier (%s) and string address which is not from + read only memory section and not from pool used for string duplicates. + String argument must be duplicated in that case using log_strdup(). + Detection is performed during log processing thus it does not impact + logging timing. + config LOG_STRDUP_MAX_STRING int "Longest string that can be duplicated using log_strdup()" default 46 if NETWORKING diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c index 795de019789..89c4eb9d420 100644 --- a/subsys/logging/log_core.c +++ b/subsys/logging/log_core.c @@ -13,6 +13,9 @@ #include #include #include +#include + +LOG_MODULE_REGISTER(log); #ifndef CONFIG_LOG_PRINTK_MAX_STRING_LENGTH #define CONFIG_LOG_PRINTK_MAX_STRING_LENGTH 1 @@ -65,11 +68,119 @@ static u32_t log_strdup_longest; static u32_t dummy_timestamp(void); static timestamp_get_t timestamp_func = dummy_timestamp; + +bool log_is_strdup(const void *buf); + static u32_t dummy_timestamp(void) { return 0; } +/** + * @brief Count number of string format specifiers (%s). + * + * Result is stored as the mask (argument n is n'th bit). Bit is set if %s was + * found. + * + * @note Algorithm does not take into account complex format specifiers as they + * hardly used in log messages and including them would significantly + * extended this function which is called on every log message is feature + * is enabled. + * + * @param str String. + * @param nargs Number of arguments in the string. + * + * @return Mask with %s format specifiers found. + */ +static u32_t count_s(const char *str, u32_t nargs) +{ + char curr; + bool arm = false; + u32_t arg = 0; + u32_t mask = 0; + + __ASSERT_NO_MSG(nargs <= 8*sizeof(mask)); + + while ((curr = *str++) && arg < nargs) { + if (curr == '%') { + arm = !arm; + } else if (arm && isalpha(curr)) { + if (curr == 's') { + mask |= BIT(arg); + } + arm = false; + arg++; + } + } + + return mask; +} + +/** + * @brief Check if address is in read only section. + * + * @param addr Address. + * + * @return True if address identified within read only section. + */ +static bool is_rodata(const void *addr) +{ +#if defined(CONFIG_ARM) || defined(CONFIG_ARC) || defined(CONIFG_RISCV32) || \ + defined(CONFIG_X86) + extern const char *_image_rodata_start[]; + extern const char *_image_rodata_end[]; + #define RO_START _image_rodata_start + #define RO_END _image_rodata_end +#elif defined(CONFIG_NIOS2) + extern const char *_image_rom_start[]; + extern const char *_image_rom_end[]; + #define RO_START _image_rom_start + #define RO_END _image_rom_end +#elif defined(CONFIG_XTENSA) + extern const char *_rodata_start[]; + extern const char *_rodata_end[]; + #define RO_START _rodata_start + #define RO_END _rodata_end +#else + #define RO_START 0 + #define RO_END 0 +#endif + + return (((const char *)addr >= (const char *)RO_START) && + ((const char *)addr < (const char *)RO_END)); +} + +/** + * @brief Scan string arguments and report evert address which is not in read + * only memory and not yet duplicated. + * + * @param msg Log message. + */ +static void detect_missed_strdup(struct log_msg *msg) +{ +#define ERR_MSG "argument %d in log message \"%s\" missing log_strdup()." + u32_t idx; + const char *str; + const char *msg_str = log_msg_str_get(msg); + u32_t mask = count_s(msg_str, log_msg_nargs_get(msg)); + + while (mask) { + idx = 31 - __builtin_clz(mask); + str = (const char *)log_msg_arg_get(msg, idx); + if (!is_rodata(str) && !log_is_strdup(str) && + (str != log_strdup_fail_msg)) { + if (IS_ENABLED(CONFIG_ASSERT)) { + __ASSERT(0, ERR_MSG, idx, msg_str); + } else { + LOG_ERR(ERR_MSG, idx, msg_str); + } + } + + mask &= ~BIT(idx); + } +#undef ERR_MSG +} + static inline void msg_finalize(struct log_msg *msg, struct log_msg_ids src_level) { @@ -444,6 +555,11 @@ static void msg_process(struct log_msg *msg, bool bypass) struct log_backend const *backend; if (!bypass) { + if (IS_ENABLED(CONFIG_LOG_DETECT_MISSED_STRDUP) && + !panic_mode) { + detect_missed_strdup(msg); + } + for (int i = 0; i < log_backend_count_get(); i++) { backend = log_backend_get(i); @@ -681,7 +797,7 @@ u32_t log_get_strdup_longest_string(void) log_strdup_longest : 0; } -bool log_is_strdup(void *buf) +bool log_is_strdup(const void *buf) { return PART_OF_ARRAY(log_strdup_pool_buf, (u8_t *)buf);