logging: Add a log flush operation

Ensure all pending log messages are processed by the log processing thread when log_flush is called, blocking the caller until done. Signed-off-by: Tom Burdick <[email protected]>
YoeDistro · Jan 15, 2025 · 5de7e41 · 5de7e41
1 parent 44d5d8a
commit 5de7e41
Show file tree

Hide file tree

Showing 4 changed files with 38 additions and 68 deletions.
diff --git a/include/zephyr/logging/log_ctrl.h b/include/zephyr/logging/log_ctrl.h
@@ -95,6 +95,17 @@ __syscall void log_panic(void);
  */
 __syscall bool log_process(void);
 
+/**
+ * @brief Process all pending log messages
+ */
+#ifdef CONFIG_LOG_MODE_DEFERRED
+void log_flush(void);
+#else
+static inline void log_flush(void)
+{
+}
+#endif
+
 /**
  * @brief Return number of buffered log messages.
  *

diff --git a/subsys/llext/llext.c b/subsys/llext/llext.c
@@ -203,60 +203,17 @@ int llext_load(struct llext_loader *ldr, const char *name, struct llext **ext,
 
 #include <zephyr/logging/log_ctrl.h>
 
-static void llext_log_flush(void)
-{
-#ifdef CONFIG_LOG_MODE_DEFERRED
-	extern struct k_thread logging_thread;
-	int cur_prio = k_thread_priority_get(k_current_get());
-	int log_prio = k_thread_priority_get(&logging_thread);
-	int target_prio;
-	bool adjust_cur, adjust_log;
-
-	/*
-	 * Our goal is to raise the logger thread priority above current, but if
-	 * current has the highest possble priority, both need to be adjusted,
-	 * particularly if the logger thread has the lowest possible priority
-	 */
-	if (log_prio < cur_prio) {
-		adjust_cur = false;
-		adjust_log = false;
-		target_prio = 0;
-	} else if (cur_prio == K_HIGHEST_THREAD_PRIO) {
-		adjust_cur = true;
-		adjust_log = true;
-		target_prio = cur_prio;
-		k_thread_priority_set(k_current_get(), cur_prio + 1);
-	} else {
-		adjust_cur = false;
-		adjust_log = true;
-		target_prio = cur_prio - 1;
-	}
-
-	/* adjust logging thread priority if needed */
-	if (adjust_log) {
-		k_thread_priority_set(&logging_thread, target_prio);
-	}
-
-	log_thread_trigger();
-	k_yield();
-
-	if (adjust_log) {
-		k_thread_priority_set(&logging_thread, log_prio);
-	}
-	if (adjust_cur) {
-		k_thread_priority_set(&logging_thread, cur_prio);
-	}
-#endif
-}
-
 int llext_unload(struct llext **ext)
 {
 	__ASSERT(*ext, "Expected non-null extension");
 	struct llext *tmp = *ext;
 
-	k_mutex_lock(&llext_lock, K_FOREVER);
+	/* Flush pending log messages, as the deferred formatting may be referencing
+	 * strings/args in the extension we are about to unload
+	 */
+	log_flush();
 
-	llext_log_flush();
+	k_mutex_lock(&llext_lock, K_FOREVER);
 
 	__ASSERT(tmp->use_count, "A valid LLEXT cannot have a zero use-count!");
 

diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c
@@ -992,4 +992,19 @@ static int enable_logger(void)
 	return 0;
 }
 
+#ifdef CONFIG_LOG_MODE_DEFERRED
+void log_flush(void)
+{
+	if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
+		while (log_data_pending()) {
+			k_sleep(K_MSEC(10));
+		}
+		k_sleep(K_MSEC(10));
+	} else {
+		while (LOG_PROCESS()) {
+		}
+	}
+}
+#endif
+
 SYS_INIT(enable_logger, POST_KERNEL, CONFIG_LOG_CORE_INIT_PRIORITY);
diff --git a/subsys/testsuite/ztest/src/ztest.c b/subsys/testsuite/ztest/src/ztest.c
@@ -934,19 +934,6 @@ static void __ztest_init_unit_test_result_for_suite(struct ztest_suite_node *sui
 	}
 }
 
-static void flush_log(void)
-{
-	if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
-		while (log_data_pending()) {
-			k_sleep(K_MSEC(10));
-		}
-		k_sleep(K_MSEC(10));
-	} else {
-		while (LOG_PROCESS()) {
-		}
-	}
-}
-
 /* Show one line summary for a test suite.
  */
 static void __ztest_show_suite_summary_oneline(struct ztest_suite_node *suite)
@@ -994,7 +981,7 @@ static void __ztest_show_suite_summary_oneline(struct ztest_suite_node *suite)
 			 TC_RESULT_TO_STR(suite_result), passrate_major, passrate_minor,
 			 suite->name, distinct_pass, distinct_fail, distinct_skip, distinct_total,
 			 suite_duration_worst_ms / 1000, suite_duration_worst_ms % 1000);
-	flush_log();
+	log_flush();
 }
 
 static void __ztest_show_suite_summary_verbose(struct ztest_suite_node *suite)
@@ -1035,12 +1022,12 @@ static void __ztest_show_suite_summary_verbose(struct ztest_suite_node *suite)
 
 		if (flush_frequency % 3 == 0) {
 			/** Reduce the flush frequency a bit to speed up the output */
-			flush_log();
+			log_flush();
 		}
 		flush_frequency++;
 	}
 	TC_SUMMARY_PRINT("\n");
-	flush_log();
+	log_flush();
 }
 
 static void __ztest_show_suite_summary(void)
@@ -1051,17 +1038,17 @@ static void __ztest_show_suite_summary(void)
 	/* Flush the log a lot to ensure that no summary content
 	 * is dropped if it goes through the logging subsystem.
 	 */
-	flush_log();
+	log_flush();
 	TC_SUMMARY_PRINT("\n------ TESTSUITE SUMMARY START ------\n\n");
-	flush_log();
+	log_flush();
 	for (struct ztest_suite_node *ptr = _ztest_suite_node_list_start;
 	     ptr < _ztest_suite_node_list_end; ++ptr) {
 
 		__ztest_show_suite_summary_oneline(ptr);
 		__ztest_show_suite_summary_verbose(ptr);
 	}
 	TC_SUMMARY_PRINT("------ TESTSUITE SUMMARY END ------\n\n");
-	flush_log();
+	log_flush();
 }
 
 static int __ztest_run_test_suite(struct ztest_suite_node *ptr, const void *state, bool shuffle,
@@ -1474,7 +1461,7 @@ int main(void)
 #ifndef CONFIG_ZTEST_SHELL
 	test_main();
 	end_report();
-	flush_log();
+	log_flush();
 	LOG_PANIC();
 	if (IS_ENABLED(CONFIG_ZTEST_RETEST_IF_PASSED)) {
 		static __noinit struct {