[PATCH i-g-t 05/28] Logs to comms

[Petri Latvala]

---
 lib/igt_core.c | 135 +++++++++++++++++++++++++++++++++++--------------
 1 file changed, 96 insertions(+), 39 deletions(-)

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 10b5be27..b44e348b 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -387,6 +387,84 @@ static void _igt_log_buffer_reset(void)
 	pthread_mutex_unlock(&log_buffer_mutex);
 }
 
+__attribute__((format(printf, 2, 3)))
+static void _log_line_fprintf(FILE* stream, const char *format, ...)
+{
+	va_list ap;
+	char *str;
+
+	va_start(ap, format);
+
+	if (runner_connected()) {
+		vasprintf(&str, format, ap);
+		send_to_runner(runnerpacket_log(fileno(stream), str));
+		free(str);
+	} else {
+		vfprintf(stream, format, ap);
+	}
+}
+
+enum _subtest_type {
+      _SUBTEST_TYPE_NORMAL,
+      _SUBTEST_TYPE_DYNAMIC,
+};
+
+static void _subtest_result_message(enum _subtest_type subtest_type,
+				    const char *name,
+				    const char *result,
+				    double timeelapsed)
+{
+	char timestr[32];
+
+	snprintf(timestr, sizeof(timestr), "%.3f", timeelapsed);
+
+	if (runner_connected()) {
+		if (subtest_type == _SUBTEST_TYPE_NORMAL)
+			send_to_runner(runnerpacket_subtest_result(name, result, timestr, NULL));
+		else
+			send_to_runner(runnerpacket_dynamic_subtest_result(name, result, timestr, NULL));
+
+		return;
+	}
+
+	printf("%s%s %s: %s (%ss)%s\n",
+	       (!__igt_plain_output) ? "\x1b[1m" : "",
+	       subtest_type == _SUBTEST_TYPE_NORMAL ? "Subtest" : "Dynamic subtest",
+	       name,
+	       result,
+	       timestr,
+	       (!__igt_plain_output) ? "\x1b[0m" : "");
+	fflush(stdout);
+	if (stderr_needs_sentinel)
+		fprintf(stderr, "%s %s: %s (%ss)\n",
+			subtest_type == _SUBTEST_TYPE_NORMAL ? "Subtest" : "Dynamic subtest",
+			name,
+			result,
+			timestr);
+}
+
+static void _subtest_starting_message(enum _subtest_type subtest_type,
+				      const char *name)
+{
+	if (runner_connected()) {
+		if (subtest_type == _SUBTEST_TYPE_NORMAL)
+			send_to_runner(runnerpacket_subtest_start(name));
+		else
+			send_to_runner(runnerpacket_dynamic_subtest_start(name));
+
+		return;
+	}
+
+	igt_info("Starting %s: %s\n",
+		 subtest_type == _SUBTEST_TYPE_NORMAL ? "subtest" : "dynamic subtest",
+		 name);
+	fflush(stdout);
+	if (stderr_needs_sentinel)
+		fprintf(stderr, "Starting %s: %s\n",
+			subtest_type == _SUBTEST_TYPE_NORMAL ? "subtest" : "dynamic subtest",
+			name);
+}
+
 static void _igt_log_buffer_dump(void)
 {
 	uint8_t i;
@@ -409,31 +487,31 @@ static void _igt_log_buffer_dump(void)
 	}
 
 	if (in_dynamic_subtest)
-		fprintf(stderr, "Dynamic subtest %s failed.\n", in_dynamic_subtest);
+		_log_line_fprintf(stderr, "Dynamic subtest %s failed.\n", in_dynamic_subtest);
 	else if (in_subtest)
-		fprintf(stderr, "Subtest %s failed.\n", in_subtest);
+		_log_line_fprintf(stderr, "Subtest %s failed.\n", in_subtest);
 	else
-		fprintf(stderr, "Test %s failed.\n", command_str);
+		_log_line_fprintf(stderr, "Test %s failed.\n", command_str);
 
 	if (log_buffer.start == log_buffer.end) {
-		fprintf(stderr, "No log.\n");
+		_log_line_fprintf(stderr, "No log.\n");
 		return;
 	}
 
 	pthread_mutex_lock(&log_buffer_mutex);
-	fprintf(stderr, "**** DEBUG ****\n");
+	_log_line_fprintf(stderr, "**** DEBUG ****\n");
 
 	i = log_buffer.start;
 	do {
 		char *last_line = log_buffer.entries[i];
-		fprintf(stderr, "%s", last_line);
+		_log_line_fprintf(stderr, "%s", last_line);
 		i++;
 	} while (i != log_buffer.start && i != log_buffer.end);
 
 	/* reset the buffer */
 	log_buffer.start = log_buffer.end = 0;
 
-	fprintf(stderr, "****  END  ****\n");
+	_log_line_fprintf(stderr, "****  END  ****\n");
 	pthread_mutex_unlock(&log_buffer_mutex);
 }
 
@@ -1258,24 +1336,15 @@ bool __igt_run_subtest(const char *subtest_name, const char *file, const int lin
 
 
 	if (skip_subtests_henceforth) {
-		printf("%sSubtest %s: %s%s\n",
-		       (!__igt_plain_output) ? "\x1b[1m" : "", subtest_name,
-		       skip_subtests_henceforth == SKIP ?
-		       "SKIP" : "FAIL", (!__igt_plain_output) ? "\x1b[0m" : "");
-		fflush(stdout);
-		if (stderr_needs_sentinel)
-			fprintf(stderr, "Subtest %s: %s\n", subtest_name,
-				skip_subtests_henceforth == SKIP ?
-				"SKIP" : "FAIL");
+		_subtest_result_message(_SUBTEST_TYPE_NORMAL, subtest_name,
+					skip_subtests_henceforth == SKIP ? "SKIP" : "FAIL",
+					0.0);
 		return false;
 	}
 
 	igt_kmsg(KMSG_INFO "%s: starting subtest %s\n",
 		 command_str, subtest_name);
-	igt_info("Starting subtest: %s\n", subtest_name);
-	fflush(stdout);
-	if (stderr_needs_sentinel)
-		fprintf(stderr, "Starting subtest: %s\n", subtest_name);
+	_subtest_starting_message(_SUBTEST_TYPE_NORMAL, subtest_name);
 
 	_igt_log_buffer_reset();
 	igt_thread_clear_fail_state();
@@ -1303,10 +1372,7 @@ bool __igt_run_dynamic_subtest(const char *dynamic_subtest_name)
 
 	igt_kmsg(KMSG_INFO "%s: starting dynamic subtest %s\n",
 		 command_str, dynamic_subtest_name);
-	igt_info("Starting dynamic subtest: %s\n", dynamic_subtest_name);
-	fflush(stdout);
-	if (stderr_needs_sentinel)
-		fprintf(stderr, "Starting dynamic subtest: %s\n", dynamic_subtest_name);
+	_subtest_starting_message(_SUBTEST_TYPE_DYNAMIC, dynamic_subtest_name);
 
 	_igt_log_buffer_reset();
 	igt_thread_clear_fail_state();
@@ -1385,23 +1451,16 @@ bool __igt_enter_dynamic_container(void)
 __noreturn static void exit_subtest(const char *result)
 {
 	struct timespec now;
-	const char *subtest_text = in_dynamic_subtest ? "Dynamic subtest" : "Subtest";
 	const char **subtest_name = in_dynamic_subtest ? &in_dynamic_subtest : &in_subtest;
 	struct timespec *thentime = in_dynamic_subtest ? &dynamic_subtest_time : &subtest_time;
 	jmp_buf *jmptarget = in_dynamic_subtest ? &igt_dynamic_jmpbuf : &igt_subtest_jmpbuf;
 
 	igt_gettime(&now);
 
-	igt_info("%s%s %s: %s (%.3fs)%s\n",
-		 (!__igt_plain_output) ? "\x1b[1m" : "",
-		 subtest_text, *subtest_name, result,
-		 igt_time_elapsed(thentime, &now),
-		 (!__igt_plain_output) ? "\x1b[0m" : "");
-	fflush(stdout);
-	if (stderr_needs_sentinel)
-		fprintf(stderr, "%s %s: %s (%.3fs)\n",
-			subtest_text, *subtest_name,
-			result, igt_time_elapsed(thentime, &now));
+	_subtest_result_message(in_dynamic_subtest ? _SUBTEST_TYPE_DYNAMIC : _SUBTEST_TYPE_NORMAL,
+				*subtest_name,
+				result,
+				igt_time_elapsed(thentime, &now));
 
 	igt_terminate_spins();
 
@@ -2815,11 +2874,9 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
 	/* prepend all except information messages with process, domain and log
 	 * level information */
 	if (level != IGT_LOG_INFO) {
-		fwrite(formatted_line, sizeof(char), strlen(formatted_line),
-		       file);
+		_log_line_fprintf(file, "%s", formatted_line);
 	} else {
-		fwrite(thread_id, sizeof(char), strlen(thread_id), file);
-		fwrite(line, sizeof(char), strlen(line), file);
+		_log_line_fprintf(file, "%s%s", thread_id, line);
 	}
 
 	pthread_mutex_unlock(&print_mutex);
-- 
2.29.2