[igt-dev] [RFC PATCH v3 4/5] igt/core: Initial simple interleaved kmsg filtering

[Daniel Vetter]

On Tue, Feb 20, 2018 at 01:30:41PM +0200, Petri Latvala wrote:
> From: Daniel Vetter <daniel.vetter at ffwll.ch>
> 
> Needs to be beefed up so that dmesg warning (and worse) are re-emmitted
> as IGT_LOG_WARN. But only if they match one of our filters (which we
> should probably allow to be extended, e.g. depending upon which driver
> has been openened). This also requires that we at least parse the
> basic of kmsg lines (adjusting the timestamp to match our own would be
> real cool).
> 
> v2:
> - Seek to the end of the kmsg buffer before starting the capturing.
> - Increase linebuffer to avoid dmesg drowning out all the tests
>   messages.
> 
> v3: Unlazy slightly and implement semi-correct kmsg parsing.
> 
> v4 (Petri): Handle continuation lines instead of crashing on them
> 
> Signed-off-by: Daniel Vetter <daniel.vetter at ffwll.ch>
> Signed-off-by: Petri Latvala <petri.latvala at intel.com>
> ---
>  lib/igt_core.c | 65 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
>  1 file changed, 64 insertions(+), 1 deletion(-)
> 
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index aaafc1df..27686276 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -293,7 +293,7 @@ static const char *command_str;
>  
>  static char* igt_debug_log_domain_filter;
>  static struct {
> -	char *entries[256];
> +	char *entries[2000];
>  	uint8_t start, end;
>  } log_buffer;
>  static pthread_mutex_t log_buffer_mutex = PTHREAD_MUTEX_INITIALIZER;
> @@ -581,6 +581,67 @@ static void oom_adjust_for_doom(void)
>  
>  }
>  
> +static void *kmsg_capture(void *arg)
> +{
> +	int kmsg_capture_fd = (uintptr_t) arg;
> +	FILE *kmsg_file = fdopen(kmsg_capture_fd, "r");
> +	char *line = NULL;
> +	size_t line_len = 0;
> +	ssize_t read;

Please add

	/* See Documentation/ABI/testing/dev-kmsg in the kernel sources */

for dummies like me who tried to reverse-engineer the uapi from the
chardev sources :-)

> +
> +	while ((read = getline(&line, &line_len, kmsg_file))) {
> +		int s;
> +		unsigned flags;
> +		unsigned long long seq, ts_usec;
> +		char continuation;
> +		enum igt_log_level level;

Reading docs we also need to handle -EPIPE:
		if (read == -1)
			if (errno = EPIPE)
				continue; /* we can get -EPIPE on buffer overflow */
			else
				break;

With those 2 changes Reviewed-by: Daniel Vetter <daniel.vetter at ffwll.ch>
on your version.

Thanks for testing this.
-Daniel

> +
> +		s = sscanf(line, "%u,%llu,%llu,%c;", &flags,
> +			   &seq, &ts_usec, &continuation);
> +
> +		if (s == 4) {
> +			if ((flags & 0x7) <= 4)
> +				level = IGT_LOG_WARN;
> +			else
> +				level = IGT_LOG_DEBUG;
> +
> +			igt_log("dmesg", level, "[%llu.%06llu], %s",
> +				ts_usec / 1000000,
> +				ts_usec % 1000000,
> +				index(line, ';') + 1);
> +		} else if (line[0] == ' ') {
> +			/* continuation line; ignore */
> +		} else {
> +			igt_warn("Cannot parse kmsg line: %s\n", line);
> +		}
> +	}
> +
> +	igt_warn("ran out of dmesg, this shouldn't happen\n");
> +
> +	free(line);
> +	fclose(kmsg_file);
> +	return NULL;
> +}
> +
> +static void start_kmsg_recording(void)
> +{
> +	static pthread_t kmsg_capture_thread;
> +	int kmsg_capture_fd;
> +
> +	kmsg_capture_fd = open("/dev/kmsg",
> +			       O_RDONLY | O_CLOEXEC);
> +
> +	if (kmsg_capture_fd < 0) {
> +		igt_info("no dmesg capturing\n");
> +		return;
> +	}
> +
> +	lseek(kmsg_capture_fd, 0, SEEK_END);
> +
> +	pthread_create(&kmsg_capture_thread, NULL,
> +		       kmsg_capture, (void *)(uintptr_t) kmsg_capture_fd);
> +}
> +
>  #ifdef HAVE_GLIB
>  static void common_init_config(void)
>  {
> @@ -814,6 +875,8 @@ out:
>  		kmsg(KERN_INFO "[IGT] %s: executing\n", command_str);
>  		print_version();
>  
> +		start_kmsg_recording();
> +
>  		sync();
>  		oom_adjust_for_doom();
>  		ftrace_dump_on_oops(true);
> -- 
> 2.11.0
> 

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch