Test automation improvements

Log files are now based on the name of the test being run, and
individual tests in a .ktest file now have their own log files

Signed-off-by: Kent Overstreet <kent.overstreet@gmail.com>

4 files changed, 145 insertions, 6 deletions

diff --git a/README.md b/README.md
index b34a413..28c0801 100644
--- a/README.md
+++ b/README.md
@@ -100,3 +100,17 @@ functions.
 
 By default, tests are shell functions that start with test. You can define tests
 differently by defining the shell functions list_tests and run_test.
+
+
+
+AUTOMATION:
+===========
+
+Output logs go in ktest-out/out/; full output from a run of a .ktest test file
+goes in
+  ktest-out/out/$basename
+
+Individual tests go in
+  ktest-out/out/$basename.$testname
+
+Success or failure will be the very last line of the per-test logfiles.
diff --git a/lib/libktest.sh b/lib/libktest.sh
index abaadf4..542af43 100644
--- a/lib/libktest.sh
+++ b/lib/libktest.sh
@@ -263,6 +263,11 @@ start_vm()
 	# timeout here is a backup:
 	qemu_cmd+=(-S -F -T $((60 + ktest_timeout)))
     fi
+
+    local test_basename=$(basename -s .ktest "$ktest_test")
+    qemu_cmd+=(-b "$test_basename")
+    qemu_cmd+=(-o "$ktest_out/out")
+
     qemu_cmd+=(--)
 
     if [[ -z $ktest_kernel_binary ]]; then
@@ -280,7 +285,11 @@ start_vm()
 
     get_tmpdir
 
-    mkdir -p "$ktest_out"
+    # Was outputting to a single log file, now a directory:
+    [[ -f $ktest_out/out ]] && rm -f "$ktest_out/out"
+
+    mkdir -p "$ktest_out/out"
+
     rm -f "$ktest_out/core.*"
     rm -f "$ktest_out/vmcore"
     rm -f "$ktest_out/vm"
@@ -421,6 +430,6 @@ start_vm()
     set -o pipefail
     shopt -s lastpipe
 
-    "${qemu_cmd[@]}"|tee "$ktest_out/out"
+    "${qemu_cmd[@]}"
     exit $?
 }
diff --git a/lib/qemu-wrapper.c b/lib/qemu-wrapper.c
index 5f52d0c..eb86656 100644
--- a/lib/qemu-wrapper.c
+++ b/lib/qemu-wrapper.c
@@ -1,7 +1,11 @@
+#define _GNU_SOURCE
+
+#include <ctype.h>
 #include <getopt.h>
 #include <errno.h>
 #include <fcntl.h>
 #include <signal.h>
+#include <stdarg.h>
 #include <stdbool.h>
 #include <stdio.h>
 #include <stdlib.h>
@@ -38,9 +42,79 @@ static void usage(void)
 	     "      -S              Exit on success\n"
 	     "      -F              Exit on failure\n"
 	     "      -T TIMEOUT      Timeout after TIMEOUT seconds\n"
+	     "      -b name         base name for log files\n"
+	     "      -o dir          output directory for log files\n"
 	     "      -h              Display this help and exit\n");
 }
 
+static char *mprintf(const char *fmt, ...)
+{
+	va_list args;
+	char *str;
+	int ret;
+
+	va_start(args, fmt);
+	ret = vasprintf(&str, fmt, args);
+	va_end(args);
+
+	if (ret < 0)
+		die("insufficient memory");
+
+	return str;
+}
+
+static char *log_path(const char *logdir, const char *basename, const char *testname)
+{
+	if (!basename)
+		basename = "out";
+
+	return !testname
+		? mprintf("%s/%s", logdir, basename)
+		: mprintf("%s/%s.%s", logdir, basename, testname);
+}
+
+static FILE *log_open(const char *logdir, const char *basename, const char *testname)
+{
+	char *path = log_path(logdir, basename, testname);
+
+	FILE *f = fopen(path, "w");
+	if (!f)
+		die("error opening %s: %m", path);
+
+	free(path);
+	setlinebuf(f);
+	return f;
+}
+
+static void strim(char *line)
+{
+	char *p = line;
+
+	while (!iscntrl(*p))
+		p++;
+	*p = 0;
+}
+
+static const char *str_starts_with(const char *str, const char *prefix)
+{
+	unsigned len = strlen(prefix);
+
+	if (strncmp(str, prefix, len))
+		return NULL;
+	return str + len;
+}
+
+static const char *test_starts(const char *line)
+{
+	return str_starts_with(line, "========= TEST   ");
+}
+
+static bool test_ends(char *line)
+{
+	return  str_starts_with(line, "========= FAILED ") ||
+		str_starts_with(line, "========= PASSED ");
+}
+
 int main(int argc, char *argv[])
 {
 	bool exit_on_success = false;
@@ -48,6 +122,8 @@ int main(int argc, char *argv[])
 	unsigned long timeout = 0;
 	int opt, ret = EXIT_FAILURE;
 	struct timespec start, ts;
+	char *logdir = NULL;
+	char *basename = NULL;
 
 	setlinebuf(stdin);
 	setlinebuf(stdout);
@@ -55,7 +131,7 @@ int main(int argc, char *argv[])
 	if (clock_gettime(CLOCK_MONOTONIC, &start))
 		die("clock_gettime error: %m");
 
-	while ((opt = getopt(argc, argv, "SFT:h")) != -1) {
+	while ((opt = getopt(argc, argv, "SFT:b:o:h")) != -1) {
 		switch (opt) {
 		case 'S':
 			exit_on_success = true;
@@ -69,6 +145,12 @@ int main(int argc, char *argv[])
 			if (errno)
 				die("error parsing timeout: %m");
 			break;
+		case 'b':
+			basename = strdup(optarg);
+			break;
+		case 'o':
+			logdir = strdup(optarg);
+			break;
 		case 'h':
 			usage();
 			exit(EXIT_SUCCESS);
@@ -78,6 +160,9 @@ int main(int argc, char *argv[])
 		}
 	}
 
+	if (!logdir)
+		die("Required option -o missing");
+
 	int pipefd[2];
 	if (pipe(pipefd))
 		die("error creating pipe: %m");
@@ -117,18 +202,48 @@ int main(int argc, char *argv[])
 		goto out;
 	}
 
-	size_t n = 0, len;
+	FILE *logfile = log_open(logdir, basename, NULL);
+	FILE *test_logfile = NULL;
+
+	size_t n = 0, output_len = 0;
+	ssize_t len;
 	char *line = NULL;
+	char *output_line = NULL;
 
 	while ((len = getline(&line, &n, childf)) >= 0) {
+		strim(line);
+
+		const char *testname = test_starts(line);
+
+		if (test_logfile &&
+		    (testname || test_ends(line))) {
+			fputc('\n', test_logfile);
+			fclose(test_logfile);
+			test_logfile = NULL;
+		}
+
 		if (clock_gettime(CLOCK_MONOTONIC, &ts)) {
 			fprintf(stderr, "clock_gettime error: %m\n");
 			break;
 		}
 
+		if (output_len < n + 20) {
+			output_len = n + 20;
+			output_line = realloc(output_line, output_len);
+		}
+
 		unsigned long elapsed = ts.tv_sec - start.tv_sec;
-		printf("%.5lu ", elapsed);
-		fputs(line, stdout);
+
+		strim(line);
+		sprintf(output_line, "%.5lu %s\n", elapsed, line);
+
+		if (test_logfile)
+			fputs(output_line, test_logfile);
+		fputs(output_line, logfile);
+		fputs(output_line, stdout);
+
+		if (testname)
+			test_logfile = log_open(logdir, basename, testname);
 
 		if (exit_on_success &&
 		    strstr(line, "TEST SUCCESS")) {
diff --git a/lib/testrunner b/lib/testrunner
index 4d871e4..6d9e1ea 100755
--- a/lib/testrunner
+++ b/lib/testrunner
@@ -17,6 +17,7 @@ ktest_tmp="/host/$ktest_tmp"
 ktest_out="/host/$ktest_out"
 
 ln -sf $ktest_dir /ktest
+ln -sf $ktest_out /ktest-out
 ln -sf /host/$home $home
 
 . "$ktest_dir/lib/util.sh"