logging: Fix false strdup buffer freeing

Algorithm for freeing strdup buffers was only checking if argument
matches address within strdup buffer pool and was attempting freeing
even if format specifier was different than string.

Added fix where also format specifier is checked.

Extended logger test to verify correctness of function which searches
for string format specifiers within a string.

Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>

include/logging/log_core.h

@@ -630,6 +630,18 @@ void log_dropped(void);
 void __printf_like(2, 3) log_from_user(struct log_msg_ids src_level,
 				       const char *fmt, ...);
 
+/**
+ * @brief Create mask with occurences of a string format specifiers (%s).
+ *
+ * Result is stored as the mask (argument n is n'th bit). Bit is set if string
+ * format specifier was found.
+ *
+ * @param str String.
+ * @param nargs Number of arguments in the string.
+ *
+ * @return Mask with %s format specifiers found.
+ */
+u32_t z_log_get_s_mask(const char *str, u32_t nargs);
 
 /* Internal function used by log_from_user(). */
 __syscall void z_log_string_from_user(u32_t src_level_val, const char *str);

subsys/logging/log_core.c

@@ -81,23 +81,7 @@ 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)
+u32_t z_log_get_s_mask(const char *str, u32_t nargs)
 {
 	char curr;
 	bool arm = false;
@@ -173,7 +157,7 @@ static void detect_missed_strdup(struct log_msg *msg)
 	}
 
 	msg_str = log_msg_str_get(msg);
-	mask = count_s(msg_str, log_msg_nargs_get(msg));
+	mask = z_log_get_s_mask(msg_str, log_msg_nargs_get(msg));
 
 	while (mask) {
 		idx = 31 - __builtin_clz(mask);

subsys/logging/log_msg.c

@@ -103,17 +103,38 @@ static void cont_free(struct log_msg_cont *cont)
 
 static void msg_free(struct log_msg *msg)
 {
-	u32_t nargs = msg->hdr.params.std.nargs;
+	u32_t nargs = log_msg_nargs_get(msg);
 
 	/* Free any transient string found in arguments. */
 	if (log_msg_is_std(msg) && nargs) {
 		int i;
+		u32_t smask = 0;
 
 		for (i = 0; i < nargs; i++) {
 			void *buf = (void *)log_msg_arg_get(msg, i);
 
 			if (log_is_strdup(buf)) {
-				log_free(buf);
+				if (smask == 0) {
+					/* Do string arguments scan only when
+					 * string duplication candidate detected
+					 * since it is time consuming and free
+					 * can be called from any context when
+					 * log message is being dropped.
+					 */
+					smask = z_log_get_s_mask(
+							log_msg_str_get(msg),
+							nargs);
+					if (smask == 0) {
+						/* if no string argument is
+						 * detected then stop searching
+						 * for candidates.
+						 */
+						break;
+					}
+				}
+				if (smask & BIT(i)) {
+					log_free(buf);
+				}
 			}
 		}
 	} else if (IS_ENABLED(CONFIG_USERSPACE) &&

tests/subsys/logging/log_core/src/log_core_test.c

@@ -477,6 +477,22 @@ static void test_log_msg_dropped_notification(void)
 	k_sched_unlock();
 }
 
+static void test_single_z_log_get_s_mask(const char *str, u32_t nargs,
+					 u32_t exp_mask)
+{
+	u32_t mask = z_log_get_s_mask(str, nargs);
+
+	zassert_equal(mask, exp_mask, "Unexpected mask %x (expected %x)",
+								mask, exp_mask);
+}
+
+static void test_z_log_get_s_mask(void)
+{
+	test_single_z_log_get_s_mask("%d%%%-10s%p%x", 4, 0x2);
+	test_single_z_log_get_s_mask("%d%d%d%d%d%d%d%d%d%d%d%d%d%d%d%d"
+				     "%d%d%d%d%d%d%d%d%d%d%d%d%d%d%d%s",
+				     32, 0x80000000);
+}
 /*
  * Test checks if panic is correctly executed. On panic logger should flush all
  * messages and process logs in place (not in deferred way).
@@ -522,6 +538,7 @@ void test_main(void)
 			 ztest_unit_test(test_log_strdup_detect_miss),
 			 ztest_unit_test(test_strdup_trimming),
 			 ztest_unit_test(test_log_msg_dropped_notification),
+			 ztest_unit_test(test_z_log_get_s_mask),
 			 ztest_unit_test(test_log_panic));
 	ztest_run_test_suite(test_log_list);
 }