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

[Daniel Vetter]

On Tue, Feb 20, 2018 at 12:50:45PM +0100, Daniel Vetter wrote:
> 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;

As a precaution against KERN_CONT lines we might want to clamp the log
level here:

			if (c == '+')
				level = IGT_LOG_DEBUG;

Assuming I'm reading the docs correctly. This should avoid continuation
lines being logged at the wrong (default = WARN) level.
-Daniel

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

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