[Intel-gfx] [PATCH] lib/core: Check for kernel error messages and FAIL if any are found

[Daniel Vetter]

On Wed, Sep 17, 2014 at 12:34:46PM +0100, Chris Wilson wrote:
> At the end of a subtest, check for any WARNs or ERRORs (or worse!)
> emitted since the start of our test and FAIL the subtest if any are
> found. This will prevent silent failures due to oops from going amiss or
> being falsely reported as TIMEOUTs.
> 
> Signed-off-by: Chris Wilson <chris at chris-wilson.co.uk>

We already have this in piglit, including filtering for non-i915 issues
(which especially on s/r tests happen a lot). So this just duplicates
that.

Also imo it's nice to differentiate between test failures and dmesg noise
in at least some tests, so clamping to fail isn't the righ thing to do I
think.
-Daniel

> ---
>  lib/igt_core.c | 114 ++++++++++++++++++++++++++++++++++++++++++++++++++++-----
>  1 file changed, 104 insertions(+), 10 deletions(-)
> 
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index 5d41468..29a262f 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -208,6 +208,7 @@ static char *run_single_subtest = NULL;
>  static bool run_single_subtest_found = false;
>  static const char *in_subtest = NULL;
>  static struct timespec subtest_time;
> +static int subtest_kmsg = -1;
>  static bool in_fixture = false;
>  static bool test_with_subtests = false;
>  static enum {
> @@ -229,14 +230,14 @@ enum {
>  
>  __attribute__((format(printf, 1, 2)))
>  static void kmsg(const char *format, ...)
> -#define KERN_EMER	"<0>"
> -#define KERN_ALERT	"<1>"
> -#define KERN_CRIT	"<2>"
> -#define KERN_ERR	"<3>"
> -#define KERN_WARNING	"<4>"
> -#define KERN_NOTICE	"<5>"
> -#define KERN_INFO	"<6>"
> -#define KERN_DEBUG	"<7>"
> +#define KMSG_EMER	"<0>"
> +#define KMSG_ALERT	"<1>"
> +#define KMSG_CRIT	"<2>"
> +#define KMSG_ERR	"<3>"
> +#define KMSG_WARNING	"<4>"
> +#define KMSG_NOTICE	"<5>"
> +#define KMSG_INFO	"<6>"
> +#define KMSG_DEBUG	"<7>"
>  {
>  	va_list ap;
>  	FILE *file;
> @@ -478,7 +479,7 @@ out:
>  		exit(ret == -1 ? 0 : IGT_EXIT_INVALID);
>  
>  	if (!list_subtests) {
> -		kmsg(KERN_INFO "%s: executing\n", command_str);
> +		kmsg(KMSG_INFO "%s: executing\n", command_str);
>  		print_version();
>  
>  		oom_adjust_for_doom();
> @@ -610,7 +611,11 @@ bool __igt_run_subtest(const char *subtest_name)
>  		return false;
>  	}
>  
> -	kmsg(KERN_INFO "%s: starting subtest %s\n", command_str, subtest_name);
> +	kmsg(KMSG_INFO "%s: starting subtest %s\n", command_str, subtest_name);
> +
> +	subtest_kmsg = open("/dev/kmsg", O_RDONLY | O_NONBLOCK);
> +	if (subtest_kmsg != -1)
> +		lseek(subtest_kmsg, 0, SEEK_END);
>  
>  	gettime(&subtest_time);
>  	return (in_subtest = subtest_name);
> @@ -643,6 +648,82 @@ static bool succeeded_one = false;
>  static bool failed_one = false;
>  static int igt_exitcode;
>  
> +static char *readfile(int fd)
> +{
> +	char *buf;
> +	int len, end;
> +
> +	end = 0;
> +	len = 4096;
> +	buf = malloc(4096);
> +	if (buf == NULL)
> +		return NULL;
> +
> +	do {
> +		char *newbuf;
> +		int rem = len - end - 1;
> +		int ret = read(fd, buf + end, rem);
> +		if (ret <= 0)
> +			break;
> +
> +		end += ret;
> +		if (ret < rem)
> +			break;
> +
> +		newbuf = realloc(buf, len *= 2);
> +		if (newbuf == NULL)
> +			break;
> +
> +		buf = newbuf;
> +	} while (1);
> +
> +	if (end == 0) {
> +		free(buf);
> +		return NULL;
> +	}
> +
> +	buf[end] = '\0';
> +	return buf;
> +}
> +
> +static int print_kernlog(char *log, int prio)
> +#define PRIO_EMER	0
> +#define PRIO_ALERT	1
> +#define PRIO_CRIT	2
> +#define PRIO_ERR	3
> +#define PRIO_WARNING	4
> +#define PRIO_NOTICE	5
> +#define PRIO_INFO	6
> +#define PRIO_DEBUG	7
> +{
> +	int count = 0;
> +
> +	do {
> +		char *s, *t;
> +		int lvl;
> +
> +		s = strchr(log, ';');
> +		if (s == NULL)
> +			break;
> +
> +		t = strchr(s + 1, '\n');
> +		if (t == NULL)
> +			break;
> +
> +		*t = '\0';
> +
> +		lvl = atoi(log);
> +		if (lvl <= prio) {
> +			puts(s+1);
> +			count++;
> +		}
> +
> +		log = t + 1;
> +	} while (*log);
> +
> +	return count;
> +}
> +
>  static void exit_subtest(const char *) __attribute__((noreturn));
>  static void exit_subtest(const char *result)
>  {
> @@ -653,7 +734,20 @@ static void exit_subtest(const char *result)
>  	elapsed = now.tv_sec - subtest_time.tv_sec;
>  	elapsed += (now.tv_nsec - subtest_time.tv_nsec) * 1e-9;
>  
> +	if (subtest_kmsg != -1) {
> +		char *log;
> +
> +		log = readfile(subtest_kmsg);
> +		if (log) {
> +			if (print_kernlog(log, PRIO_WARNING))
> +				result = "FAIL";
> +			free(log);
> +		}
> +		close(subtest_kmsg);
> +	}
> +
>  	printf("Subtest %s: %s (%.3fs)\n", in_subtest, result, elapsed);
> +
>  	in_subtest = NULL;
>  	longjmp(igt_subtest_jmpbuf, 1);
>  }
> -- 
> 2.1.0
> 
> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx at lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/intel-gfx

-- 
Daniel Vetter
Software Engineer, Intel Corporation
+41 (0) 79 365 57 48 - http://blog.ffwll.ch