[PATCH i-g-t v4] lib/igt_core: Add kmsg capture and dumping

Joonas Lahtinen
2015-11-26T12:17:58Z

Capture the output from /dev/kmsg during test execution independantly
of other concurrent watchers like Piglit test runner.

The captured output is analyzed and the whole output dumped if message
with priority LOG_WARNING or higher is emitted from any domain.

Also adding igt_capture to lib/tests which will fail subtests and
produce kmsg output which should be captured by the new code.

v4:
- Do not effect return value of test, just dump (Daniel)

v3:
- Use O_CLOEXEC and clarify hex decoding (Chris)

v2:
- Reopen/close the kmsg FD per each test (Chris)
- Better commit mesage (Daniel)
- Display failure due to kmsg only as FAIL (KMSG)

Cc: Thomas Wood <thomas.wood@intel.com>
Cc: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Damien Lespiau <damien.lespiau@intel.com>
Cc: Daniel Vetter <daniel.vetter@ffwll.ch>
Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>
Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
---
lib/igt_core.c | 129 +++++++++++++++++++++++++++++++++++++++++++--
lib/tests/.gitignore | 1 +
lib/tests/Makefile.sources | 2 +
lib/tests/igt_capture.c | 89 +++++++++++++++++++++++++++++++
4 files changed, 218 insertions(+), 3 deletions(-)
create mode 100644 lib/tests/igt_capture.c

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 84cf8d2..b1aa750 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -43,6 +43,7 @@
#include <getopt.h>
#include <stdlib.h>
#include <unistd.h>
+#include <syslog.h>
#include <sys/wait.h>
#include <sys/types.h>
#ifdef __linux__
@@ -211,6 +212,8 @@
* "--help" command line option.
*/

+#define IGT_KMSG_DUMP_BUF_SIZE 4096
+
static unsigned int exit_handler_count;
const char *igt_interactive_debug;

@@ -248,6 +251,10 @@ enum {
static int igt_exitcode = IGT_EXIT_SUCCESS;
static const char *command_str;

+static int igt_kmsg_capture_fd = -1;
+static int igt_kmsg_check_fd = -1;
+static char* igt_kmsg_dump_buf = NULL;
+
static char* igt_log_domain_filter;
static struct {
char *entries[256];
@@ -313,6 +320,112 @@ static void _igt_log_buffer_dump(void)
pthread_mutex_unlock(&log_buffer_mutex);
}

+static void _igt_kmsg_reset(void)
+{
+ if (igt_kmsg_dump_buf == NULL)
+ igt_kmsg_dump_buf = malloc(IGT_KMSG_DUMP_BUF_SIZE);
+
+ if (igt_kmsg_dump_buf == NULL) {
+ igt_warn("Unable to allocate memory, "
+ "can not dump kmsg.\n");
+ return;
+ }
+
+ if (igt_kmsg_capture_fd == -1)
+ igt_kmsg_capture_fd = open("/dev/kmsg",
+ O_RDONLY | O_NONBLOCK | O_CLOEXEC);
+
+ if (igt_kmsg_capture_fd == -1)
+ goto err_capture;
+
+ if (igt_kmsg_check_fd == -1)
+ igt_kmsg_check_fd = open("/dev/kmsg",
+ O_RDONLY | O_NONBLOCK | O_CLOEXEC);
+
+ if (igt_kmsg_check_fd == -1)
+ goto err_check;
+
+ lseek(igt_kmsg_capture_fd, 0, SEEK_END);
+ lseek(igt_kmsg_check_fd, 0, SEEK_END);
+ return;
+
+err_check:
+ close(igt_kmsg_capture_fd);
+ igt_kmsg_capture_fd = -1;
+err_capture:
+ free(igt_kmsg_dump_buf);
+ igt_kmsg_dump_buf = NULL;
+ return;
+}
+
+static int _igt_kmsg_dump(bool print, int filter_priority)
+{
+ size_t nbytes;
+ int nlines;
+ int prefix;
+ int priority;
+ char *p;
+ int fd;
+
+ fd = print ? igt_kmsg_capture_fd : igt_kmsg_check_fd;
+ if (fd == -1)
+ return 0;
+
+ nlines = 0;
+ do {
+ errno = 0;
+ nbytes = read(fd, igt_kmsg_dump_buf, IGT_KMSG_DUMP_BUF_SIZE);
+
+ if (nbytes == -1)
+ continue;
+
+ sscanf(igt_kmsg_dump_buf, "%d;", &prefix);
+ priority = prefix & 0x7;
+
+ if (priority > filter_priority)
+ continue;
+
+ nlines++;
+
+ if (!print)
+ continue;
+
+ if (nlines == 1)
+ fprintf(stderr, "**** KMSG ****\n");
+
+ p = strchr(igt_kmsg_dump_buf, ';') + 1;
+ while (p - igt_kmsg_dump_buf < nbytes) {
+ int c = *p++;
+ /* Decode non-printable characters escaped in
+ * hex form (\x0f). */
+ if (c == '\\') {
+ igt_assert(*p++ == 'x');
+ igt_assert(sscanf(p, "%x", &c) == 1);
+ p += 2;
+ }
+ fputc(c, stderr);
+ }
+ } while(errno == 0);
+
+ if (print && nlines)
+ fprintf(stderr, "**** END ****\n");
+
+ if (errno != EAGAIN)
+ fprintf(stderr, "Error: Incomplete kmsg!\n");
+
+ close(fd);
+
+ if (print) {
+ igt_kmsg_capture_fd = -1;
+ free(igt_kmsg_dump_buf);
+ igt_kmsg_dump_buf = NULL;
+ } else {
+ igt_kmsg_check_fd = -1;
+ }
+
+ return nlines;
+}
+
__attribute__((format(printf, 1, 2)))
static void kmsg(const char *format, ...)
#define KERN_EMER "<0>"
@@ -712,8 +825,10 @@ out:
/* install exit handler, to ensure we clean up */
igt_install_exit_handler(common_exit_handler);

- if (!test_with_subtests)
+ if (!test_with_subtests) {
gettime(&subtest_time);
+ _igt_kmsg_reset();
+ }

for (i = 0; (optind + i) < *argc; i++)
argv[i + 1] = argv[optind + i];
@@ -832,8 +947,9 @@ bool __igt_run_subtest(const char *subtest_name)
igt_debug("Starting subtest: %s\n", subtest_name);

_igt_log_buffer_reset();
-
+ _igt_kmsg_reset();
gettime(&subtest_time);
+
return (in_subtest = subtest_name);
}

@@ -963,6 +1079,9 @@ void __igt_skip_check(const char *file, const int line,
*/
void igt_success(void)
{
+ if (_igt_kmsg_dump(false, LOG_WARNING))
+ _igt_kmsg_dump(true, LOG_DEBUG);
+
succeeded_one = true;
if (in_subtest)
exit_subtest("SUCCESS");
@@ -1005,6 +1124,11 @@ void igt_fail(int exitcode)

_igt_log_buffer_dump();

+ /* Show kmsg if not already shown. */
+ if (_igt_kmsg_dump(true, LOG_DEBUG) < 1)
+ fprintf(stderr, "No kmsg.\n");
+
+
if (in_subtest) {
if (exitcode == IGT_EXIT_TIMEOUT)
exit_subtest("TIMEOUT");
@@ -1111,7 +1235,6 @@ void igt_exit(void)
exit(IGT_EXIT_INVALID);
}

-
if (igt_only_list_subtests())
exit(IGT_EXIT_SUCCESS);

diff --git a/lib/tests/.gitignore b/lib/tests/.gitignore
index a4f1080..c49c178 100644
--- a/lib/tests/.gitignore
+++ b/lib/tests/.gitignore
@@ -1,5 +1,6 @@
# Please keep sorted alphabetically
igt_assert
+igt_capture
igt_fork_helper
igt_invalid_subtest_name
igt_list_only
diff --git a/lib/tests/Makefile.sources b/lib/tests/Makefile.sources
index 777b9c1..6506baf 100644
--- a/lib/tests/Makefile.sources
+++ b/lib/tests/Makefile.sources
@@ -1,4 +1,5 @@
check_PROGRAMS = \
+ igt_capture \
igt_no_exit \
igt_no_exit_list_only \
igt_fork_helper \
@@ -32,4 +33,5 @@ XFAIL_TESTS = \
igt_simple_test_subtests \
igt_timeout \
igt_invalid_subtest_name \
+ igt_capture \
$(NULL)
diff --git a/lib/tests/igt_capture.c b/lib/tests/igt_capture.c
new file mode 100644
index 0000000..28ffce1
--- /dev/null
+++ b/lib/tests/igt_capture.c
@@ -0,0 +1,89 @@
+/*
+ * Copyright © 2015 Intel Corporation
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a
+ * copy of this software and associated documentation files (the "Software"),
+ * to deal in the Software without restriction, including without limitation
+ * the rights to use, copy, modify, merge, publish, distribute, sublicense,
+ * and/or sell copies of the Software, and to permit persons to whom the
+ * Software is furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice (including the next
+ * paragraph) shall be included in all copies or substantial portions of the
+ * Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL
+ * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
+ * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
+ * IN THE SOFTWARE.
+ *
+ * Authors:
+ * Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
+ *
+ */
+
+#include "igt_core.h"
+#include <stdio.h>
+#include <syslog.h>
+
+static FILE* kmsg;
+
+static void
+test_kmsg(bool fail)
+{
+ fprintf(kmsg, "<%d>TEST (KMSG)\n", LOG_WARNING);
+ fflush(kmsg);
+ if (fail)
+ igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_warn(void)
+{
+ igt_warn("TEST (WARN)\n");
+ igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_debug(void)
+{
+ igt_debug("TEST (DEBUG)\n");
+ igt_fail(IGT_EXIT_FAILURE);
+}
+
+static void
+test_combined(void)
+{
+ igt_warn("TEST #1 (WARN)\n");
+ fputs("TEST #1\n", kmsg);
+ igt_warn("TEST #2 (WARN)\n");
+ fputs("TEST #2\n", kmsg);
+ fflush(kmsg);
+ igt_fail(IGT_EXIT_FAILURE);
+}
+
+igt_main
+{
+ igt_fixture {
+ kmsg = fopen("/dev/kmsg", "w");
+ igt_require(kmsg != NULL);
+ }
+
+ igt_subtest("kmsg")
+ test_kmsg(true);
+ igt_subtest("kmsg-success")
+ test_kmsg(false);
+ igt_subtest("warn")
+ test_warn();
+ igt_subtest("debug")
+ test_debug();
+ igt_subtest("combined")
+ test_combined();
+
+ igt_fixture {
+ fclose(kmsg);
+ }
+}
--
2.4.3