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>

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
 ===============
 

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.
  *

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

subsys/logging/log_core.c

@@ -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);