[Intel-gfx] [PATCH] lib/core: Check for kernel error messages and FAIL if any are found

[Chris Wilson]

At the end of a subtest, check for any WARNs or ERRORs (or worse!)
emitted since the start of our test and FAIL the subtest if any are
found. This will prevent silent failures due to oops from going amiss or
being falsely reported as TIMEOUTs.

Signed-off-by: Chris Wilson <chris at chris-wilson.co.uk>
---
 lib/igt_core.c | 114 ++++++++++++++++++++++++++++++++++++++++++++++++++++-----
 1 file changed, 104 insertions(+), 10 deletions(-)

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 5d41468..29a262f 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -208,6 +208,7 @@ static char *run_single_subtest = NULL;
 static bool run_single_subtest_found = false;
 static const char *in_subtest = NULL;
 static struct timespec subtest_time;
+static int subtest_kmsg = -1;
 static bool in_fixture = false;
 static bool test_with_subtests = false;
 static enum {
@@ -229,14 +230,14 @@ enum {
 
 __attribute__((format(printf, 1, 2)))
 static void kmsg(const char *format, ...)
-#define KERN_EMER	"<0>"
-#define KERN_ALERT	"<1>"
-#define KERN_CRIT	"<2>"
-#define KERN_ERR	"<3>"
-#define KERN_WARNING	"<4>"
-#define KERN_NOTICE	"<5>"
-#define KERN_INFO	"<6>"
-#define KERN_DEBUG	"<7>"
+#define KMSG_EMER	"<0>"
+#define KMSG_ALERT	"<1>"
+#define KMSG_CRIT	"<2>"
+#define KMSG_ERR	"<3>"
+#define KMSG_WARNING	"<4>"
+#define KMSG_NOTICE	"<5>"
+#define KMSG_INFO	"<6>"
+#define KMSG_DEBUG	"<7>"
 {
 	va_list ap;
 	FILE *file;
@@ -478,7 +479,7 @@ out:
 		exit(ret == -1 ? 0 : IGT_EXIT_INVALID);
 
 	if (!list_subtests) {
-		kmsg(KERN_INFO "%s: executing\n", command_str);
+		kmsg(KMSG_INFO "%s: executing\n", command_str);
 		print_version();
 
 		oom_adjust_for_doom();
@@ -610,7 +611,11 @@ bool __igt_run_subtest(const char *subtest_name)
 		return false;
 	}
 
-	kmsg(KERN_INFO "%s: starting subtest %s\n", command_str, subtest_name);
+	kmsg(KMSG_INFO "%s: starting subtest %s\n", command_str, subtest_name);
+
+	subtest_kmsg = open("/dev/kmsg", O_RDONLY | O_NONBLOCK);
+	if (subtest_kmsg != -1)
+		lseek(subtest_kmsg, 0, SEEK_END);
 
 	gettime(&subtest_time);
 	return (in_subtest = subtest_name);
@@ -643,6 +648,82 @@ static bool succeeded_one = false;
 static bool failed_one = false;
 static int igt_exitcode;
 
+static char *readfile(int fd)
+{
+	char *buf;
+	int len, end;
+
+	end = 0;
+	len = 4096;
+	buf = malloc(4096);
+	if (buf == NULL)
+		return NULL;
+
+	do {
+		char *newbuf;
+		int rem = len - end - 1;
+		int ret = read(fd, buf + end, rem);
+		if (ret <= 0)
+			break;
+
+		end += ret;
+		if (ret < rem)
+			break;
+
+		newbuf = realloc(buf, len *= 2);
+		if (newbuf == NULL)
+			break;
+
+		buf = newbuf;
+	} while (1);
+
+	if (end == 0) {
+		free(buf);
+		return NULL;
+	}
+
+	buf[end] = '\0';
+	return buf;
+}
+
+static int print_kernlog(char *log, int prio)
+#define PRIO_EMER	0
+#define PRIO_ALERT	1
+#define PRIO_CRIT	2
+#define PRIO_ERR	3
+#define PRIO_WARNING	4
+#define PRIO_NOTICE	5
+#define PRIO_INFO	6
+#define PRIO_DEBUG	7
+{
+	int count = 0;
+
+	do {
+		char *s, *t;
+		int lvl;
+
+		s = strchr(log, ';');
+		if (s == NULL)
+			break;
+
+		t = strchr(s + 1, '\n');
+		if (t == NULL)
+			break;
+
+		*t = '\0';
+
+		lvl = atoi(log);
+		if (lvl <= prio) {
+			puts(s+1);
+			count++;
+		}
+
+		log = t + 1;
+	} while (*log);
+
+	return count;
+}
+
 static void exit_subtest(const char *) __attribute__((noreturn));
 static void exit_subtest(const char *result)
 {
@@ -653,7 +734,20 @@ static void exit_subtest(const char *result)
 	elapsed = now.tv_sec - subtest_time.tv_sec;
 	elapsed += (now.tv_nsec - subtest_time.tv_nsec) * 1e-9;
 
+	if (subtest_kmsg != -1) {
+		char *log;
+
+		log = readfile(subtest_kmsg);
+		if (log) {
+			if (print_kernlog(log, PRIO_WARNING))
+				result = "FAIL";
+			free(log);
+		}
+		close(subtest_kmsg);
+	}
+
 	printf("Subtest %s: %s (%.3fs)\n", in_subtest, result, elapsed);
+
 	in_subtest = NULL;
 	longjmp(igt_subtest_jmpbuf, 1);
 }
-- 
2.1.0