logging: Prevent multiple arguments evaluation

Logging v2 is utilizing complex preprocessing operations to
prepare message at compile time. Multiple operations are peformed
on log message arguments. However, it is expected that argument
will be evaluated only once (e.g. it can be a call to a function
with side effects). Adding additional layer which creates copies
of user arguments on stack and passes them to further processing.

Updated test for log_msg2 which is using internal macro which
got renamed.

Signed-off-by: Krzysztof Chruscinski <[email protected]>

Author: nordic-krch

include/logging/log_msg2.h

@@ -344,7 +344,7 @@ do { \
  * @param ...  Optional string with arguments (fmt, ...). It may be empty.
  */
 #ifdef CONFIG_LOG2_ALWAYS_RUNTIME
-#define Z_LOG_MSG2_CREATE2(_try_0cpy, _mode,  _cstr_cnt, _domain_id, _source,\
+#define Z_LOG_MSG2_CREATE3(_try_0cpy, _mode,  _cstr_cnt, _domain_id, _source,\
 			  _level, _data, _dlen, ...) \
 do {\
 	Z_LOG_MSG2_STR_VAR(_fmt, ##__VA_ARGS__) \
@@ -354,7 +354,7 @@ do {\
 	_mode = Z_LOG_MSG2_MODE_RUNTIME; \
 } while (0)
 #elif defined(CONFIG_LOG_MODE_IMMEDIATE) /* CONFIG_LOG2_ALWAYS_RUNTIME */
-#define Z_LOG_MSG2_CREATE2(_try_0cpy, _mode,  _cstr_cnt, _domain_id, _source,\
+#define Z_LOG_MSG2_CREATE3(_try_0cpy, _mode,  _cstr_cnt, _domain_id, _source,\
 			  _level, _data, _dlen, ...) \
 do { \
 	Z_LOG_MSG2_STR_VAR(_fmt, ##__VA_ARGS__); \
@@ -371,7 +371,7 @@ do { \
 	} \
 } while (0)
 #else /* CONFIG_LOG2_ALWAYS_RUNTIME */
-#define Z_LOG_MSG2_CREATE2(_try_0cpy, _mode,  _cstr_cnt, _domain_id, _source,\
+#define Z_LOG_MSG2_CREATE3(_try_0cpy, _mode,  _cstr_cnt, _domain_id, _source,\
 			  _level, _data, _dlen, ...) \
 do { \
 	Z_LOG_MSG2_STR_VAR(_fmt, ##__VA_ARGS__); \
@@ -396,12 +396,41 @@ do { \
 } while (0)
 #endif /* CONFIG_LOG2_ALWAYS_RUNTIME */
 
-#define Z_LOG_MSG2_CREATE(_try_0cpy, _mode,  _domain_id, _source,\
+#define Z_LOG_MSG2_CREATE2(_try_0cpy, _mode,  _domain_id, _source,\
 			  _level, _data, _dlen, ...) \
-	Z_LOG_MSG2_CREATE2(_try_0cpy, _mode, UTIL_CAT(Z_LOG_FUNC_PREFIX_, _level), \
+	Z_LOG_MSG2_CREATE3(_try_0cpy, _mode, UTIL_CAT(Z_LOG_FUNC_PREFIX_, _level), \
 			   _domain_id, _source, _level, _data, _dlen, \
 			   Z_LOG_STR(_level, __VA_ARGS__))
 
+/* Macro for getting name of a local variable with the exception of the first argument
+ * which is a formatted string in log message.
+ */
+#define Z_LOG_LOCAL_ARG_NAME(idx, arg) COND_CODE_0(idx, (arg), (_v##idx))
+
+/* Create local variable from input variable (expect first (fmt) argument). */
+#ifdef __cplusplus
+#define Z_LOG_LOCAL_ARG_CREATE(idx, arg) \
+	COND_CODE_0(idx, (), (auto Z_LOG_LOCAL_ARG_NAME(idx, arg) = (arg) + 0))
+#else
+#define Z_LOG_LOCAL_ARG_CREATE(idx, arg) \
+	COND_CODE_0(idx, (), (__auto_type Z_LOG_LOCAL_ARG_NAME(idx, arg) = (arg) + 0))
+#endif
+
+/* First level of processing creates stack variables to be passed for further processing.
+ * This is done to prevent multiple evaluations of input arguments (in case argument
+ * evaluation has consequences, e.g. it is a function call).
+ */
+#define Z_LOG_MSG2_CREATE(_try_0cpy, _mode,  _domain_id, _source, _level, _data, _dlen, ...) \
+do { \
+	_Pragma("GCC diagnostic push") \
+	_Pragma("GCC diagnostic ignored \"-Wpointer-arith\"") \
+	FOR_EACH_IDX(Z_LOG_LOCAL_ARG_CREATE, (;), __VA_ARGS__); \
+	_Pragma("GCC diagnostic pop") \
+	Z_LOG_MSG2_CREATE2(_try_0cpy, _mode,  _domain_id, _source,\
+			   _level, _data, _dlen, \
+			   FOR_EACH_IDX(Z_LOG_LOCAL_ARG_NAME, (,), __VA_ARGS__)); \
+} while (0)
+
 /** @brief Allocate log message.
  *
  * @param wlen Length in 32 bit words.

tests/subsys/logging/log_msg2/src/main.c

@@ -189,11 +189,11 @@ void test_log_msg2_0_args_msg(void)
 	test_init();
 	printk("Test string:%s\n", TEST_MSG);
 
-	Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level,
+	Z_LOG_MSG2_CREATE3(1, mode, 0, domain, source, level,
 			  NULL, 0, TEST_MSG);
 	zassert_equal(mode, EXP_MODE(ZERO_COPY), NULL);
 
-	Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level,
+	Z_LOG_MSG2_CREATE3(0, mode, 0, domain, source, level,
 			  NULL, 0, TEST_MSG);
 	zassert_equal(mode, EXP_MODE(FROM_STACK), NULL);
 
@@ -222,11 +222,11 @@ void test_log_msg2_various_args(void)
 	test_init();
 	printk("Test string:%s\n", TEST_MSG);
 
-	Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, NULL, 0,
+	Z_LOG_MSG2_CREATE3(1, mode, 0, domain, source, level, NULL, 0,
 			TEST_MSG, s8, u, lld, (void *)str, lld, (void *)iarray);
 	zassert_equal(mode, EXP_MODE(ZERO_COPY), NULL);
 
-	Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, NULL, 0,
+	Z_LOG_MSG2_CREATE3(0, mode, 0, domain, source, level, NULL, 0,
 			TEST_MSG, s8, u, lld, (void *)str, lld, (void *)iarray);
 	zassert_equal(mode, EXP_MODE(FROM_STACK), NULL);
 
@@ -249,11 +249,11 @@ void test_log_msg2_only_data(void)
 
 	test_init();
 
-	Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, array,
+	Z_LOG_MSG2_CREATE3(1, mode, 0, domain, source, level, array,
 			   sizeof(array));
 	zassert_equal(mode, EXP_MODE(FROM_STACK), NULL);
 
-	Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, array,
+	Z_LOG_MSG2_CREATE3(0, mode, 0, domain, source, level, array,
 			   sizeof(array));
 	zassert_equal(mode, EXP_MODE(FROM_STACK), NULL);
 
@@ -278,11 +278,11 @@ void test_log_msg2_string_and_data(void)
 
 	test_init();
 
-	Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, array,
+	Z_LOG_MSG2_CREATE3(1, mode, 0, domain, source, level, array,
 			   sizeof(array), TEST_MSG);
 	zassert_equal(mode, EXP_MODE(FROM_STACK), NULL);
 
-	Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, array,
+	Z_LOG_MSG2_CREATE3(0, mode, 0, domain, source, level, array,
 			   sizeof(array), TEST_MSG);
 	zassert_equal(mode, EXP_MODE(FROM_STACK), NULL);
 
@@ -315,11 +315,11 @@ void test_log_msg2_fp(void)
 
 	test_init();
 
-	Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, NULL, 0,
+	Z_LOG_MSG2_CREATE3(1, mode, 0, domain, source, level, NULL, 0,
 			TEST_MSG, i, lli, (double)f, &i, d, source);
 	zassert_equal(mode, EXP_MODE(ZERO_COPY), NULL);
 
-	Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, NULL, 0,
+	Z_LOG_MSG2_CREATE3(0, mode, 0, domain, source, level, NULL, 0,
 			TEST_MSG, i, lli, (double)f, &i, d, source);
 	zassert_equal(mode, EXP_MODE(FROM_STACK), NULL);
 
@@ -354,12 +354,12 @@ void test_mode_size_plain_string(void)
 	uint32_t exp_len;
 	int mode;
 
-	Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, NULL, 0,
+	Z_LOG_MSG2_CREATE3(1, mode, 0, domain, source, level, NULL, 0,
 			"test str");
 	zassert_equal(mode, EXP_MODE(ZERO_COPY),
 			"Unexpected creation mode");
 
-	Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, NULL, 0,
+	Z_LOG_MSG2_CREATE3(0, mode, 0, domain, source, level, NULL, 0,
 			"test str");
 	zassert_equal(mode, EXP_MODE(FROM_STACK),
 			"Unexpected creation mode");
@@ -393,7 +393,7 @@ void test_mode_size_data_only(void)
 	 */
 	uint8_t data[] = {1, 2, 3};
 
-	Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level,
+	Z_LOG_MSG2_CREATE3(1, mode, 0, domain, source, level,
 			   data, sizeof(data));
 	zassert_equal(mode, EXP_MODE(FROM_STACK),
 			"Unexpected creation mode");
@@ -421,7 +421,7 @@ void test_mode_size_plain_str_data(void)
 	 */
 	uint8_t data[] = {1, 2, 3};
 
-	Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level,
+	Z_LOG_MSG2_CREATE3(1, mode, 0, domain, source, level,
 			   data, sizeof(data), "test");
 	zassert_equal(mode, EXP_MODE(FROM_STACK),
 			"Unexpected creation mode");
@@ -450,13 +450,13 @@ void test_mode_size_str_with_strings(void)
 	int mode;
 	static const char *prefix = "prefix";
 
-	Z_LOG_MSG2_CREATE2(1, mode,
+	Z_LOG_MSG2_CREATE3(1, mode,
 			   1 /* accept one string pointer*/,
 			   domain, source, level,
 			   NULL, 0, "test %s", prefix);
 	zassert_equal(mode, EXP_MODE(ZERO_COPY),
 			"Unexpected creation mode");
-	Z_LOG_MSG2_CREATE2(0, mode,
+	Z_LOG_MSG2_CREATE3(0, mode,
 			   1 /* accept one string pointer*/,
 			   domain, source, level,
 			   NULL, 0, "test %s", prefix);
@@ -489,13 +489,13 @@ void test_mode_size_str_with_2strings(void)
 	int mode;
 	static const char *prefix = "prefix";
 
-	Z_LOG_MSG2_CREATE2(1, mode,
+	Z_LOG_MSG2_CREATE3(1, mode,
 			   1 /* accept one string pointer*/,
 			   domain, source, level,
 			   NULL, 0, TEST_STR, prefix, "sufix");
 	zassert_equal(mode, EXP_MODE(RUNTIME),
 			"Unexpected creation mode");
-	Z_LOG_MSG2_CREATE2(0, mode,
+	Z_LOG_MSG2_CREATE3(0, mode,
 			   1 /* accept one string pointer*/,
 			   domain, source, level,
 			   NULL, 0, TEST_STR, prefix, "sufix");
@@ -546,14 +546,14 @@ void test_saturate(void)
 	log_set_timestamp_func(timestamp_get_inc, 0);
 
 	for (int i = 0; i < exp_capacity; i++) {
-		Z_LOG_MSG2_CREATE2(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test");
+		Z_LOG_MSG2_CREATE3(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test");
 	}
 
 	zassert_equal(z_log_dropped_read_and_clear(), 0, "No dropped messages.");
 
 	/* Message should not fit in and be dropped. */
-	Z_LOG_MSG2_CREATE2(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test");
-	Z_LOG_MSG2_CREATE2(0, mode, 0, 0, (void *)1, 2, NULL, 0, "test");
+	Z_LOG_MSG2_CREATE3(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test");
+	Z_LOG_MSG2_CREATE3(0, mode, 0, 0, (void *)1, 2, NULL, 0, "test");
 	z_log_msg2_runtime_create(0, (void *)1, 2, NULL, 0, "test");
 
 	zassert_equal(z_log_dropped_read_and_clear(), 3, "No dropped messages.");