logging: Add option to detect missed transient string duplication
Added CONFIG_LOG_DETECT_MISSED_STRDUP (by default on) which enables scanning of log message strings in search for %s and reports if string address is not from strdup buffer pool and outside read only memory section which indicates that log_strdup() wrapping is missing Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
This commit is contained in:
parent
d6176f8697
commit
a211afb041
4 changed files with 139 additions and 2 deletions
|
@ -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
|
||||
===============
|
||||
|
||||
|
|
|
@ -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.
|
||||
*
|
||||
|
|
|
@ -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
|
||||
|
|
|
@ -13,6 +13,9 @@
|
|||
#include <init.h>
|
||||
#include <assert.h>
|
||||
#include <atomic.h>
|
||||
#include <ctype.h>
|
||||
|
||||
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);
|
||||
|
||||
|
|
Loading…
Add table
Add a link
Reference in a new issue