diff mbox

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

Message ID 1447929323-19370-1-git-send-email-joonas.lahtinen@linux.intel.com (mailing list archive)
State New, archived
Headers show

Commit Message

Joonas Lahtinen Nov. 19, 2015, 10:35 a.m. UTC 
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

Comments

Chris Wilson Nov. 19, 2015, 11:32 a.m. UTC | #1 
On Thu, Nov 19, 2015 at 12:35:23PM +0200, Joonas Lahtinen wrote:
> +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);

We should O_CLOEXEC as well.

> +
> +	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");

If we allocate first, then bail, we know if we have the fd we have the
buffer as well.

> +}
> +
> +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;

i.e. we can just do if (fd == -1) 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;

Maybe:
	/* Decode non-printable characters escaped by '\x01' */
	int c = *p++;
	if (c == '\\') {
		if (p - igt_kmgs_capture_dump_buf > nbytes - 3)
			break;
		sscanf(p+1, "%x", &c);
		p += 3;
	}
	fputc(c, stderr);

> +		}
> +		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;

Hmm, single-shot.

I have in mind more of an automatic debug feature coupled with error
detection like how we automatically go back and print the debug log if
the test fails. As I understand it, with a FAIL (KMSG) we currently lose
any lower priority output.

The integration looks good to me otherwise. But someone else will have
to vouch for test-runner/piglit handling of "FAIL (KMSG)" (I used WARN).
-Chris
Joonas Lahtinen Nov. 20, 2015, 11:46 a.m. UTC | #2 
On to, 2015-11-19 at 11:32 +0000, Chris Wilson wrote:
> On Thu, Nov 19, 2015 at 12:35:23PM +0200, Joonas Lahtinen wrote:
> > +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);
> 
> We should O_CLOEXEC as well.
> 

Fixed.

> > +
> > +	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");
> 
> If we allocate first, then bail, we know if we have the fd we have
> the
> buffer as well.
> 

I was thinking we would still perform as much of the actions that would
be done if we were able to dump the kmsg, for consistency. That is why
the buffer allocation is handled separately. But maybe it's bit
overkill.

> > +}
> > +
> > +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;
> 
> i.e. we can just do if (fd == -1) 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;
> 
> Maybe:
> 	/* Decode non-printable characters escaped by '\x01' */
> 	int c = *p++;
> 	if (c == '\\') {
> 		if (p - igt_kmgs_capture_dump_buf > nbytes - 3)
> 			break;
> 		sscanf(p+1, "%x", &c);
> 		p += 3;
> 	}
> 	fputc(c, stderr);
> 

I'll simplify this bit.

> > +		}
> > +		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;
> 
> Hmm, single-shot.
> 
> I have in mind more of an automatic debug feature coupled with error
> detection like how we automatically go back and print the debug log
> if
> the test fails. As I understand it, with a FAIL (KMSG) we currently
> lose
> any lower priority output.
> 

Yeah, unless we allocate buffers and store when we start reading, it
has to be dumped as we read. This also causes the one thing I don't
like in the current implementation is that the KMSG appears before the
debug output. The /dev/kmsg doesn't want to be seeked (even the
documentation states that, attempted that initially regardless), so our
only option is to allocate buffers dynamically or estimate maximum
buffer size and go with that.

> The integration looks good to me otherwise. But someone else will
> have
> to vouch for test-runner/piglit handling of "FAIL (KMSG)" (I used
> WARN).

I think we could make NOTICE and WARN cause WARN (KMSG) and rest a FAIL
(KMSG) ?

Regards, Joonas

> -Chris
>
diff mbox

Patch

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);
+	}
+}