runner: Handle escaped characters from kmsg

Characters in kernel logs, when read from /dev/kmsg, are escaped as
\xNN if they are not between 32 and 127 of if they are "\". Decode
what we can when creating results.json.

Signed-off-by: Petri Latvala <petri.latvala@intel.com>
Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: Arkadiusz Hiler <arkadiusz.hiler@intel.com>
Reviewed-by: Arkadiusz Hiler <arkadiusz.hiler@intel.com>

13 files changed, 158 insertions, 2 deletions

diff --git a/runner/json_tests_data/dmesg-escapes/0/dmesg.txt b/runner/json_tests_data/dmesg-escapes/0/dmesg.txt
new file mode 100644
index 00000000..a585c03a
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/0/dmesg.txt
@@ -0,0 +1,13 @@
+6,951,3216186095083,-;Console: switching to colour dummy device 80x25
+14,952,3216186095097,-;[IGT] successtest: executing
+14,953,3216186101115,-;[IGT] successtest: starting subtest first-subtest
+6,954,3216186101159,-;String with a\x0anewline
+6,954,3216186101159,-;String with a\x09tab
+6,954,3216186101159,-;String with an explicit\x00NUL
+6,954,3216186101159,-;The character \x13 should be nonprintable
+6,954,3216186101159,-;Escaped backslash is \x5c
+6,954,3216186101159,-;Kernel shouldn't output this but cutoff escape \x1
+6,954,3216186101159,-;More cutoff \x
+6,954,3216186101159,-;One more \
+14,955,3216186101160,-;[IGT] successtest: exiting, ret=0
+6,956,3216186101299,-;Console: switching to colour frame buffer device 240x75
diff --git a/runner/json_tests_data/dmesg-escapes/0/err.txt b/runner/json_tests_data/dmesg-escapes/0/err.txt
new file mode 100644
index 00000000..5dc78057
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/0/err.txt
@@ -0,0 +1,2 @@
+Starting subtest: first-subtest
+Subtest first-subtest: SUCCESS (0.000s)
diff --git a/runner/json_tests_data/dmesg-escapes/0/journal.txt b/runner/json_tests_data/dmesg-escapes/0/journal.txt
new file mode 100644
index 00000000..86a30e07
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/0/journal.txt
@@ -0,0 +1,2 @@
+first-subtest
+exit:0 (0.014s)
diff --git a/runner/json_tests_data/dmesg-escapes/0/out.txt b/runner/json_tests_data/dmesg-escapes/0/out.txt
new file mode 100644
index 00000000..5946bf31
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/0/out.txt
@@ -0,0 +1,3 @@
+IGT-Version: 1.23-g0c763bfd (x86_64) (Linux: 4.18.0-1-amd64 x86_64)
+Starting subtest: first-subtest
+Subtest first-subtest: SUCCESS (0.000s)
diff --git a/runner/json_tests_data/dmesg-escapes/README.txt b/runner/json_tests_data/dmesg-escapes/README.txt
new file mode 100644
index 00000000..fbb7c6c4
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/README.txt
@@ -0,0 +1,4 @@
+Unprintable characters in kernel logs, when read via /dev/kmsg, are
+escaped as \xNN where NN the character's ascii code in hex. Those are
+expected to be decoded to results, if they really are
+printable. Kernel's idea of nonprintable is "c < 0x20 || c > 127".
diff --git a/runner/json_tests_data/dmesg-escapes/endtime.txt b/runner/json_tests_data/dmesg-escapes/endtime.txt
new file mode 100644
index 00000000..635f6ae9
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/endtime.txt
@@ -0,0 +1 @@
+1539953735.172373
diff --git a/runner/json_tests_data/dmesg-escapes/joblist.txt b/runner/json_tests_data/dmesg-escapes/joblist.txt
new file mode 100644
index 00000000..81f914a7
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/joblist.txt
@@ -0,0 +1 @@
+successtest first-subtest
diff --git a/runner/json_tests_data/dmesg-escapes/metadata.txt b/runner/json_tests_data/dmesg-escapes/metadata.txt
new file mode 100644
index 00000000..c501ae0e
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/metadata.txt
@@ -0,0 +1,12 @@
+abort_mask : 0
+name : normal-run
+dry_run : 0
+sync : 0
+log_level : 0
+overwrite : 0
+multiple_mode : 0
+inactivity_timeout : 0
+use_watchdog : 0
+piglit_style_dmesg : 0
+test_root : /path/does/not/exist
+results_path : /path/does/not/exist
diff --git a/runner/json_tests_data/dmesg-escapes/reference.json b/runner/json_tests_data/dmesg-escapes/reference.json
new file mode 100644
index 00000000..9b4df640
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/reference.json
@@ -0,0 +1,72 @@
+{
+  "__type__":"TestrunResult",
+  "results_version":9,
+  "name":"normal-run",
+  "uname":"Linux hostname 4.18.0-1-amd64 #1 SMP Debian 4.18.6-1 (2018-09-06) x86_64",
+  "time_elapsed":{
+    "__type__":"TimeAttribute",
+    "start":1539953735.1110389,
+    "end":1539953735.1723731
+  },
+  "tests":{
+    "igt@successtest@first-subtest":{
+      "out":"Starting subtest: first-subtest\nSubtest first-subtest: SUCCESS (0.000s)\n",
+      "igt-version":"IGT-Version: 1.23-g0c763bfd (x86_64) (Linux: 4.18.0-1-amd64 x86_64)",
+      "result":"pass",
+      "time":{
+        "__type__":"TimeAttribute",
+        "start":0,
+        "end":0
+      },
+      "err":"Starting subtest: first-subtest\nSubtest first-subtest: SUCCESS (0.000s)\n",
+	"dmesg":"<6> [3216186.095083] Console: switching to colour dummy device 80x25\n<6> [3216186.095097] [IGT] successtest: executing\n<6> [3216186.101115] [IGT] successtest: starting subtest first-subtest\n<6> [3216186.101159] String with a\nnewline\n<6> [3216186.101159] String with a\ttab\n<6> [3216186.101159] String with an explicit\\x00NUL\n<6> [3216186.101159] The character \\x13 should be nonprintable\n<6> [3216186.101159] Escaped backslash is \\\n<6> [3216186.101159] Kernel shouldn't output this but cutoff escape \\x1\n<6> [3216186.101159] More cutoff \\x\n<6> [3216186.101159] One more \\\n<6> [3216186.101160] [IGT] successtest: exiting, ret=0\n<6> [3216186.101299] Console: switching to colour frame buffer device 240x75\n",
+    },
+  },
+  "totals":{
+    "":{
+      "crash":0,
+      "pass":1,
+      "dmesg-fail":0,
+      "dmesg-warn":0,
+      "skip":0,
+      "incomplete":0,
+      "timeout":0,
+      "notrun":0,
+      "fail":0,
+      "warn":0
+    },
+    "root":{
+      "crash":0,
+      "pass":1,
+      "dmesg-fail":0,
+      "dmesg-warn":0,
+      "skip":0,
+      "incomplete":0,
+      "timeout":0,
+      "notrun":0,
+      "fail":0,
+      "warn":0
+    },
+    "igt@successtest":{
+      "crash":0,
+      "pass":1,
+      "dmesg-fail":0,
+      "dmesg-warn":0,
+      "skip":0,
+      "incomplete":0,
+      "timeout":0,
+      "notrun":0,
+      "fail":0,
+      "warn":0
+    },
+  },
+  "runtimes":{
+    "igt@successtest":{
+      "time":{
+        "__type__":"TimeAttribute",
+        "start":0,
+        "end":0.014
+      }
+    },
+  }
+}
diff --git a/runner/json_tests_data/dmesg-escapes/starttime.txt b/runner/json_tests_data/dmesg-escapes/starttime.txt
new file mode 100644
index 00000000..ae038f18
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/starttime.txt
@@ -0,0 +1 @@
+1539953735.111039
diff --git a/runner/json_tests_data/dmesg-escapes/uname.txt b/runner/json_tests_data/dmesg-escapes/uname.txt
new file mode 100644
index 00000000..a7aef6f7
--- /dev/null
+++ b/runner/json_tests_data/dmesg-escapes/uname.txt
@@ -0,0 +1 @@
+Linux hostname 4.18.0-1-amd64 #1 SMP Debian 4.18.6-1 (2018-09-06) x86_64
diff --git a/runner/resultgen.c b/runner/resultgen.c
index b0933ad7..659b5e62 100644
--- a/runner/resultgen.c
+++ b/runner/resultgen.c
@@ -552,6 +552,50 @@ static bool parse_dmesg_line(char* line,
 	return true;
 }
 
+static void generate_formatted_dmesg_line(char *message,
+					  unsigned flags,
+					  unsigned long long ts_usec,
+					  char **formatted)
+{
+	char prefix[512];
+	size_t messagelen;
+	size_t prefixlen;
+	char *p, *f;
+
+	snprintf(prefix, sizeof(prefix),
+		 "<%u> [%llu.%06llu] ",
+		 flags & 0x07,
+		 ts_usec / 1000000,
+		 ts_usec % 1000000);
+
+	messagelen = strlen(message);
+	prefixlen = strlen(prefix);
+
+	/*
+	 * Decoding the hex escapes only makes the string shorter, so
+	 * we can use the original length
+	 */
+	*formatted = malloc(strlen(prefix) + messagelen + 1);
+	strcpy(*formatted, prefix);
+
+	f = *formatted + prefixlen;
+	for (p = message; *p; p++, f++) {
+		if (p - message + 4 < messagelen &&
+		    p[0] == '\\' && p[1] == 'x') {
+			int c = 0;
+			/* newline and tab are not isprint(), but they are isspace() */
+			if (sscanf(p, "\\x%2x", &c) == 1 &&
+			    (isprint(c) || isspace(c))) {
+				*f = c;
+				p += 3;
+				continue;
+			}
+		}
+		*f = *p;
+	}
+	*f = '\0';
+}
+
 static void add_dmesg(struct json_object *obj,
 		      const char *dmesg, size_t dmesglen,
 		      const char *warnings, size_t warningslen)
@@ -616,8 +660,7 @@ static bool fill_from_dmesg(int fd,
 		if (!parse_dmesg_line(line, &flags, &ts_usec, &continuation, &message))
 			continue;
 
-		asprintf(&formatted, "<%u> [%llu.%06llu] %s",
-			 flags & 0x07, ts_usec / 1000000, ts_usec % 1000000, message);
+		generate_formatted_dmesg_line(message, flags, ts_usec, &formatted);
 
 		if ((subtest = strstr(message, STARTING_SUBTEST_DMESG)) != NULL) {
 			if (current_test != NULL) {
diff --git a/runner/runner_json_tests.c b/runner/runner_json_tests.c
index 75d6237f..17b81524 100644
--- a/runner/runner_json_tests.c
+++ b/runner/runner_json_tests.c
@@ -156,6 +156,7 @@ static const char *dirnames[] = {
 	"dmesg-results",
 	"aborted-on-boot",
 	"aborted-after-a-test",
+	"dmesg-escapes",
 };
 
 igt_main