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

Joonas Lahtinen
2015-11-26T15:00:17Z

On to, 2015-11-26 at 15:34 +0100, Daniel Vetter wrote:
> 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.
>

Actually, if you look at the code I copied;

fprintf(stderr, "**** DEBUG ****\n");

So, I was just trying to make it consistent with the existing output.

Would you like both converted to use igt_warn or igt_debug?

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

Should I just make it optional runtime flag --dmesg for the time being?

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

It actually tests the igt_warn and igt_debug too, so figured it could
be a generic name.

Regards, Joonas

--
Joonas Lahtinen
Open Source Technology Center
Intel Corporation