Commit 5de7e415 authored by Tom Burdick's avatar Tom Burdick Committed by Benjamin Cabé
Browse files

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: default avatarTom Burdick <thomas.burdick@intel.com>
parent 44d5d8ae

include/zephyr/logging/log_ctrl.h

+11 −0
Changes for include/zephyr/logging/log_ctrl.h: 11 added lines, 0 removed lines.
Original line number Diff line number Diff line
@@ -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.

 *

subsys/llext/llext.c

+5 −48
Changes for subsys/llext/llext.c: 5 added lines, 48 removed lines.
Original line number Diff line number Diff line
@@ -203,60 +203,17 @@ out: 


#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!");

subsys/logging/log_core.c

+15 −0
Changes for subsys/logging/log_core.c: 15 added lines, 0 removed lines.
Original line number Diff line number Diff line
@@ -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);

subsys/testsuite/ztest/src/ztest.c

+7 −20
Changes for subsys/testsuite/ztest/src/ztest.c: 7 added lines, 20 removed lines.
Original line number Diff line number Diff line
@@ -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,9 +1038,9 @@ 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) {
@@ -1061,7 +1048,7 @@ static void __ztest_show_suite_summary(void) 
		__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 {

CRA Git | Maintained and supported by SUSTech CRA and CCSE