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

[Daniel Vetter <daniel@ffwll.ch>]

On Thu, Nov 26, 2015 at 02:17:53PM +0200, Joonas Lahtinen wrote:
> 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>

Hm I guess we need to strike that ack again, more comments below.

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

Please use the igt logging functions we have. This holds in general,
please don't use any of the raw output functions and instead use the
igt_warn/info/debug stuff in your entire patch for logging.

Also the problem with dumping into stderr is that this is at the igt_warn
level, which means if this happens your test will be considered a failure
in CI.

And there's plenty of drivers and other stuff that dump random crap at
this level into dmesg, especially over system suspend resume. Which means
your patch will regress a pile of BAT igts.

We really, really need to filter dmesg the same way as piglit does. And I
mean _exactly_ the same way. Otherwise there's differences in test status,
and that means noise in CI and frustration all around.

Other option is to dump at igt_info or igt_debug level.

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

igt_dmesg_capture?

Cheers, Daniel

> @@ -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
> 

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx