From f81cdf9d3a475b6135c0951d1c7169f226164baf Mon Sep 17 00:00:00 2001 From: Petri Latvala Date: Tue, 13 Nov 2018 13:22:51 +0200 Subject: 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 Cc: Tvrtko Ursulin Cc: Arkadiusz Hiler Reviewed-by: Arkadiusz Hiler --- runner/json_tests_data/dmesg-escapes/0/dmesg.txt | 13 ++++ runner/json_tests_data/dmesg-escapes/0/err.txt | 2 + runner/json_tests_data/dmesg-escapes/0/journal.txt | 2 + runner/json_tests_data/dmesg-escapes/0/out.txt | 3 + runner/json_tests_data/dmesg-escapes/README.txt | 4 ++ runner/json_tests_data/dmesg-escapes/endtime.txt | 1 + runner/json_tests_data/dmesg-escapes/joblist.txt | 1 + runner/json_tests_data/dmesg-escapes/metadata.txt | 12 ++++ .../json_tests_data/dmesg-escapes/reference.json | 72 ++++++++++++++++++++++ runner/json_tests_data/dmesg-escapes/starttime.txt | 1 + runner/json_tests_data/dmesg-escapes/uname.txt | 1 + runner/resultgen.c | 47 +++++++++++++- runner/runner_json_tests.c | 1 + 13 files changed, 158 insertions(+), 2 deletions(-) create mode 100644 runner/json_tests_data/dmesg-escapes/0/dmesg.txt create mode 100644 runner/json_tests_data/dmesg-escapes/0/err.txt create mode 100644 runner/json_tests_data/dmesg-escapes/0/journal.txt create mode 100644 runner/json_tests_data/dmesg-escapes/0/out.txt create mode 100644 runner/json_tests_data/dmesg-escapes/README.txt create mode 100644 runner/json_tests_data/dmesg-escapes/endtime.txt create mode 100644 runner/json_tests_data/dmesg-escapes/joblist.txt create mode 100644 runner/json_tests_data/dmesg-escapes/metadata.txt create mode 100644 runner/json_tests_data/dmesg-escapes/reference.json create mode 100644 runner/json_tests_data/dmesg-escapes/starttime.txt create mode 100644 runner/json_tests_data/dmesg-escapes/uname.txt (limited to 'runner') 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 -- cgit v1.2.3