[Intel-gfx] [PATCH i-g-t 1/5] lib: print recent log output if a test fails

[Thomas Wood]

Print recent log entries if a test or subtest fails and the current log
level is set to info.

v2: Write log to stderr after test or subtest failure and make log
    buffering thread safe.

Signed-off-by: Thomas Wood <thomas.wood at intel.com>
---
 lib/igt_core.c | 103 +++++++++++++++++++++++++++++++++++++++++++++++++++++----
 1 file changed, 96 insertions(+), 7 deletions(-)

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 08e0c47..457b3b1 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -50,6 +50,8 @@
 #include <termios.h>
 #include <errno.h>
 #include <time.h>
+#include <limits.h>
+#include <pthread.h>
 
 #include "drmtest.h"
 #include "intel_chipset.h"
@@ -228,8 +230,18 @@ enum {
  OPT_HELP = 'h'
 };
 
+static const char *command_str;
+static int igt_exitcode = IGT_EXIT_SUCCESS;
+
 static char* igt_log_domain_filter;
 
+static struct {
+	char *entries[256];
+	uint8_t start, end;
+} log_buffer;
+static pthread_mutex_t log_buffer_mutex = PTHREAD_MUTEX_INITIALIZER;
+
+
 __attribute__((format(printf, 1, 2)))
 static void kmsg(const char *format, ...)
 #define KERN_EMER	"<0>"
@@ -353,6 +365,52 @@ static void low_mem_killer_disable(bool disable)
 	chmod(adj_fname, buf.st_mode);
 }
 
+#define write_log_msg(x) write(STDERR_FILENO, x, strlen(x))
+
+/* this function must be safe to be called inside a signal handler */
+static void write_log(void)
+{
+	uint8_t i;
+	char *last_line;
+
+	pthread_mutex_lock(&log_buffer_mutex);
+
+	/* don't write an empty log */
+	if (log_buffer.start == log_buffer.end) {
+		pthread_mutex_unlock(&log_buffer_mutex);
+		return;
+	}
+
+	if (in_subtest) {
+		write_log_msg("--- Subtest ");
+		write_log_msg(in_subtest);
+	} else {
+		write_log_msg("--- Test ");
+		write_log_msg(command_str);
+	}
+	write_log_msg(" failed.\n");
+	write_log_msg("--- Log Start\n");
+
+	i = log_buffer.start;
+	do {
+		last_line = log_buffer.entries[i];
+		write_log_msg(last_line);
+
+		/* ensure each line ends in a newline */
+		for (int pos = 0; last_line[pos] != '\0'; pos++) {
+			if (last_line[pos] != '\n'
+			    && last_line[pos + 1] == '\0')
+				write_log_msg("\n");
+		}
+
+		i++;
+	} while (i != log_buffer.start && i != log_buffer.end);
+
+	write_log_msg("--- Log End\n");
+
+	pthread_mutex_unlock(&log_buffer_mutex);
+}
+
 bool igt_exit_called;
 static void common_exit_handler(int sig)
 {
@@ -361,6 +419,14 @@ static void common_exit_handler(int sig)
 	/* When not killed by a signal check that igt_exit() has been properly
 	 * called. */
 	assert(sig != 0 || igt_exit_called);
+
+	/* write the log out to a file if a signal was received or a simple
+	 * test failed (tests with subtests write the log after the subtest
+	 * failure) */
+	if (sig || (!test_with_subtests
+		    && igt_exitcode != IGT_EXIT_SUCCESS
+		    && igt_exitcode != IGT_EXIT_SKIP))
+		write_log();
 }
 
 static void print_test_description(void)
@@ -383,8 +449,6 @@ static void print_version(void)
 		uts.sysname, uts.release, uts.machine);
 }
 
-static const char *command_str;
-
 static void print_usage(const char *help_str, bool output_on_stderr)
 {
 	FILE *f = output_on_stderr ? stderr : stdout;
@@ -728,7 +792,6 @@ bool igt_only_list_subtests(void)
 static bool skipped_one = false;
 static bool succeeded_one = false;
 static bool failed_one = false;
-static int igt_exitcode = IGT_EXIT_SUCCESS;
 
 static void exit_subtest(const char *) __attribute__((noreturn));
 static void exit_subtest(const char *result)
@@ -862,6 +925,7 @@ void igt_fail(int exitcode)
 		exit(exitcode);
 
 	if (in_subtest) {
+		write_log();
 		if (exitcode == IGT_EXIT_TIMEOUT)
 			exit_subtest("TIMEOUT");
 		else
@@ -1460,6 +1524,7 @@ void igt_log(const char *domain, enum igt_log_level level, const char *format, .
 void igt_vlog(const char *domain, enum igt_log_level level, const char *format, va_list args)
 {
 	FILE *file;
+	char *line;
 	const char *program_name;
 	const char *igt_log_level_str[] = {
 		"DEBUG",
@@ -1479,16 +1544,37 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
 	if (list_subtests)
 		return;
 
+	vasprintf(&line, format, args);
+
+	/* save log output when log level is info */
+	if (igt_log_level == IGT_LOG_INFO) {
+		pthread_mutex_lock(&log_buffer_mutex);
+
+		free(log_buffer.entries[log_buffer.end]);
+		asprintf(&log_buffer.entries[log_buffer.end],
+			 "(%s:%d) %s%s%s: %s",
+			 program_name, getpid(),
+			 (domain) ? domain : "",
+			 (domain) ? "-" : "",
+			 igt_log_level_str[level],
+			 line);
+		log_buffer.end++;
+		if (log_buffer.end == log_buffer.start)
+			log_buffer.start++;
+
+		pthread_mutex_unlock(&log_buffer_mutex);
+	}
+
 	if (igt_log_level > level)
-		return;
+		goto out;
 
 	if (igt_log_domain_filter) {
 		/* if null domain and filter is not "application", return */
 		if (!domain && strcmp(igt_log_domain_filter, "application"))
-			return;
+			goto out;
 		/* else if domain and filter do not match, return */
 		else if (domain && strcmp(igt_log_domain_filter, domain))
-			return;
+			goto out;
 	}
 
 	if (level == IGT_LOG_WARN) {
@@ -1503,7 +1589,10 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
 			(domain) ? domain : "", (domain) ? "-" : "",
 			igt_log_level_str[level]);
 	}
-	vfprintf(file, format, args);
+	fwrite(line, sizeof(char), strlen(line), file);
+
+out:
+	free(line);
 }
 
 static void igt_alarm_handler(int signal)
-- 
2.1.0