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

Joonas Lahtinen
2015-11-19T10:35:29Z

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 test will fail if log messages
with higher priority than LOG_NOTICE are emitted from any domain.

Also adding igt_capture to lib/tests which will fail and produce kmsg
output which should be captured by the new code and also demonstrate
failing just due to /dev/kmsg.

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>
Acked-by: Daniel Vetter <daniel.vetter@ffwll.ch>
Signed-off-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
---
lib/igt_core.c | 113 +++++++++++++++++++++++++++++++++++++++++++--
lib/igt_core.h | 7 +++
lib/tests/.gitignore | 1 +
lib/tests/Makefile.sources | 1 +
lib/tests/igt_capture.c | 88 +++++++++++++++++++++++++++++++++++
5 files changed, 207 insertions(+), 3 deletions(-)
create mode 100644 lib/tests/igt_capture.c

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 04a0ab2..cb782dc 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_CAPTURE_DUMP_BUF_SIZE 4096
+
static unsigned int exit_handler_count;
const char *igt_interactive_debug;

@@ -247,6 +250,9 @@ enum {
static int igt_exitcode = IGT_EXIT_SUCCESS;
static const char *command_str;

+static int igt_kmsg_capture_fd = -1;
+static char* igt_kmsg_capture_dump_buf = NULL;
+
static char* igt_log_domain_filter;
static struct {
char *entries[256];
@@ -312,6 +318,93 @@ static void _igt_log_buffer_dump(void)
pthread_mutex_unlock(&log_buffer_mutex);
}

+static void _igt_kmsg_capture_reset(void)
+{
+ if (igt_kmsg_capture_fd != -1)
+ close(igt_kmsg_capture_fd);
+
+ igt_kmsg_capture_fd = open("/dev/kmsg",
+ O_RDONLY | O_NONBLOCK);
+
+ if (igt_kmsg_capture_fd == -1)
+ return;
+
+ lseek(igt_kmsg_capture_fd, 0, SEEK_END);
+
+ if (igt_kmsg_capture_dump_buf == NULL)
+ igt_kmsg_capture_dump_buf =
+ malloc(IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
+
+ if (igt_kmsg_capture_dump_buf == NULL)
+ igt_warn("Unable to allocate memory, "
+ "will not dump kmsg.\n");
+}
+
+static int _igt_kmsg_capture_dump(bool notify_empty, int show_priority)
+{
+ size_t nbytes;
+ int nlines;
+ int prefix;
+ int facility;
+ int priority;
+ char *p;
+ int c;
+
+ if (igt_kmsg_capture_fd == -1 ||
+ igt_kmsg_capture_dump_buf == NULL)
+ return 0;
+
+ nlines = 0;
+ do {
+ errno = 0;
+ nbytes = read(igt_kmsg_capture_fd,
+ igt_kmsg_capture_dump_buf,
+ IGT_KMSG_CAPTURE_DUMP_BUF_SIZE);
+
+ if (nbytes == -1)
+ continue;
+
+ sscanf(igt_kmsg_capture_dump_buf, "%d;", &prefix);
+ priority = prefix & 0x7;
+
+ if (priority > show_priority)
+ continue;
+
+ if (!nlines)
+ fprintf(stderr, "**** KMSG ****\n");
+
+ p = strchr(igt_kmsg_capture_dump_buf, ';') + 1;
+ while (p - igt_kmsg_capture_dump_buf < nbytes) {
+ if (*p != '\\') {
+ fputc(*p++, stderr);
+ continue;
+ }
+ sscanf(p, "\\x%x", &c);
+ fputc(c, stderr);
+ p += 4;
+ }
+ nlines++;
+ } while(errno == 0);
+
+ if (nlines) {
+ fprintf(stderr, "**** END ****\n");
+ } else {
+ if (notify_empty)
+ fprintf(stderr, "No kmsg.\n");
+ }
+
+ if (errno != EAGAIN)
+ fprintf(stderr, "Error: Incomplete kmsg!\n");
+
+ close(igt_kmsg_capture_fd);
+ igt_kmsg_capture_fd = -1;
+
+ free(igt_kmsg_capture_dump_buf);
+ igt_kmsg_capture_dump_buf = NULL;
+
+ return nlines;
+}
+
__attribute__((format(printf, 1, 2)))
static void kmsg(const char *format, ...)
#define KERN_EMER "<0>"
@@ -676,8 +769,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_capture_reset();
+ }

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

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

@@ -931,6 +1027,9 @@ void __igt_skip_check(const char *file, const int line,
*/
void igt_success(void)
{
+ if (_igt_kmsg_capture_dump(false, LOG_NOTICE))
+ return igt_fail(IGT_EXIT_FAILURE_KMSG);
+
succeeded_one = true;
if (in_subtest)
exit_subtest("SUCCESS");
@@ -971,11 +1070,17 @@ void igt_fail(int exitcode)
if (test_child)
exit(exitcode);

+ /* Show kmsg if not already shown. */
+ if (exitcode != IGT_EXIT_FAILURE_KMSG)
+ _igt_kmsg_capture_dump(true, LOG_DEBUG);
+
_igt_log_buffer_dump();

if (in_subtest) {
if (exitcode == IGT_EXIT_TIMEOUT)
exit_subtest("TIMEOUT");
+ else if (exitcode == IGT_EXIT_FAILURE_KMSG)
+ exit_subtest("FAIL (KMSG)");
else
exit_subtest("FAIL");
} else {
@@ -1079,7 +1184,6 @@ void igt_exit(void)
exit(IGT_EXIT_INVALID);
}

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

@@ -1105,6 +1209,9 @@ void igt_exit(void)
case IGT_EXIT_SKIP:
result = "SKIP";
break;
+ case IGT_EXIT_FAILURE_KMSG:
+ result = "FAIL (KMSG)";
+ break;
default:
result = "FAIL";
}
diff --git a/lib/igt_core.h b/lib/igt_core.h
index a244fc3..3a9f41b 100644
--- a/lib/igt_core.h
+++ b/lib/igt_core.h
@@ -93,6 +93,13 @@ extern bool __igt_plain_output;
*/
#define IGT_EXIT_FAILURE 99

+/**
+ * IGT_EXIT_FAILURE_KMSG
+ *
+ * Exit status indicing printk warnings/errors during test
+ */
+#define IGT_EXIT_FAILURE_KMSG 98
+
bool __igt_fixture(void);
void __igt_fixture_complete(void);
void __igt_fixture_end(void) __attribute__((noreturn));
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..d2b5e08 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 \
diff --git a/lib/tests/igt_capture.c b/lib/tests/igt_capture.c
new file mode 100644
index 0000000..3a9c528
--- /dev/null
+++ b/lib/tests/igt_capture.c
@@ -0,0 +1,88 @@
+/*
+ * 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>
+
+static FILE* kmsg;
+
+static void
+test_kmsg(bool fail)
+{
+ fputs("TEST (KMSG)\n", kmsg);
+ 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