[igt-dev] [RFC PATCH i-g-t v5 4/6] igt/core: Initial simple interleaved kmsg filtering

[Petri Latvala]

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

v5 (Petri): Handle EPIPE, handle fragment continuations, point to
 format docs

Signed-off-by: Daniel Vetter <daniel.vetter at ffwll.ch>
Signed-off-by: Petri Latvala <petri.latvala at intel.com>
---
 lib/igt_core.c | 87 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 86 insertions(+), 1 deletion(-)

diff --git a/lib/igt_core.c b/lib/igt_core.c
index aaafc1df..86f18a21 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,89 @@ static void oom_adjust_for_doom(void)
 
 }
 
+static void *kmsg_capture(void *arg)
+{
+	/*
+	 * See Documentation/ABI/testing/dev-kmsg in the kernel
+	 * sources for documentation on the message format.
+	 */
+
+	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;
+
+	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;
+
+		if (read < 0) {
+			if (errno == EPIPE)
+				/* We can get EPIPE on buffer overflow */
+				continue;
+			else
+				break;
+		}
+
+		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;
+
+			if (continuation == 'c')
+				/*
+				 * KERN_CONT fragment, log level in
+				 * this log record is the default log
+				 * level instead of the one the
+				 * fragment continues.
+				 */
+				level = IGT_LOG_DEBUG;
+
+			igt_log("dmesg", level, "[%llu.%06llu], %s",
+				ts_usec / 1000000,
+				ts_usec % 1000000,
+				index(line, ';') + 1);
+		} else if (line[0] == ' ') {
+			/* Machine readable key/value pairs, 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 +897,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.14.1