[igt-dev] [PATCH i-g-t v3 1/1] lib/core: Use whitelist with kmsg filter

[Petri Latvala]

On Thu, Mar 01, 2018 at 11:31:49AM +0000, Chris Wilson wrote:
> Quoting Petri Latvala (2018-03-01 11:15:21)
> > dmesg messages of level >=warn don't result in an IGT_LOG_WARN if they
> > match a whitelist regexp now.
> > 
> > The whitelist is not configureable without rebuilding, and it's not
> > even possible to use a different whitelist for different drivers;
> > launching the kmsg monitor happens way before opening the driver (if
> > any).
> > 
> > v2: Use static and a less yelling variable name for the whitelist,
> >     compare to REG_NOMATCH directly, construct the regexp in a nicer
> >     looking way (Chris). Be more verbose when monitoring stops.
> > v3: More patterns, document them.
> > 
> > Signed-off-by: Petri Latvala <petri.latvala at intel.com>
> > ---
> >  lib/igt_core.c | 48 ++++++++++++++++++++++++++++++++++++++++++++++--
> >  1 file changed, 46 insertions(+), 2 deletions(-)
> > 
> > diff --git a/lib/igt_core.c b/lib/igt_core.c
> > index 0b3bf49e..6bcf004a 100644
> > --- a/lib/igt_core.c
> > +++ b/lib/igt_core.c
> > @@ -55,6 +55,7 @@
> >  #include <limits.h>
> >  #include <locale.h>
> >  #include <uwildmat/uwildmat.h>
> > +#include <regex.h>
> >  #ifdef HAVE_GLIB
> >  #include <glib.h>
> >  #endif
> > @@ -572,6 +573,37 @@ static void oom_adjust_for_doom(void)
> >  
> >  }
> >  
> > +/*
> > + * This regexp controls the kmsg monitor handling. All kernel log
> > + * records that have log level of warning or higher get inserted into
> > + * IGT log buffer with an IGT_LOG_WARN unless they match this
> > + * regexp. Otherwise they get inserted at IGT_LOG_DEBUG.
> > + */
> > +
> > +#define _ "|"
> > +static const char igt_dmesg_whitelist[] =
> > +       "ACPI: button: The lid device is not compliant to SW_LID" _
> > +       "ACPI: .*: Unable to dock!" _
> > +       "IRQ [0-9]+: no longer affine to CPU[0-9]+" _
> > +       "IRQ fixup: irq [0-9]+ move in progress, old vector [0-9]+" _
> 
> And throw in newlines to visually break up the comment groups.


Yeah. Also, TODO: Comment all lines.



> > +       /* i915 tests set module options, expected message */
> > +       "Setting dangerous option [a-z_]+ - tainting kernel" _
> 
> > +       /* Raw printk() call, uses default log level (warn) */
> > +       "Suspending console\\(s\\) \\(use no_console_suspend to debug\\)" _
> > +       "atkbd serio[0-9]+: Failed to (deactivate|enable) keyboard on isa[0-9]+/serio[0-9]+" _
> > +       "cache: parent cpu[0-9]+ should not be sleeping" _
> > +       "hpet[0-9]+: lost [0-9]+ rtc interrupts" _
> 
> > +       /* i915 selftests terminate normally with ENODEV from the
> > +        * module load after the testing finishes, which produces this
> > +        * message.
> > +        */
> > +       "i915: probe of [0-9:.]+ failed with error -25" _
> 
> > +       /* swiotbl warns even when asked not to */
> > +       "mock: DMA: Out of SW-IOMMU space for [0-9]+ bytes" _
> 
> > +       "usb usb[0-9]+: root hub lost power or was reset"
> > +       ;
> > +#undef _
> > +
> >  static void *kmsg_capture(void *arg)
> >  {
> >         /*
> > @@ -584,6 +616,13 @@ static void *kmsg_capture(void *arg)
> >         char *line = NULL;
> >         size_t line_len = 0;
> >         ssize_t read;
> > +       regex_t re;
> > +
> > +       if (regcomp(&re, igt_dmesg_whitelist, REG_EXTENDED | REG_NOSUB) != 0) {
> > +               igt_warn("Cannot compile dmesg whitelist regexp\n");
> > +               fclose(kmsg_file);
> > +               return NULL;
> > +       }
> >  
> >         while ((read = getline(&line, &line_len, kmsg_file))) {
> >                 int s;
> > @@ -604,7 +643,8 @@ static void *kmsg_capture(void *arg)
> >                            &seq, &ts_usec, &continuation);
> >  
> >                 if (s == 4) {
> > -                       if ((flags & 0x7) <= 4)
> > +                       if ((flags & 0x7) <= 4 &&
> > +                           regexec(&re, line, (size_t)0, NULL, 0) == REG_NOMATCH)
> >                                 level = IGT_LOG_WARN;
> >                         else
> >                                 level = IGT_LOG_DEBUG;
> > @@ -629,7 +669,11 @@ static void *kmsg_capture(void *arg)
> >                 }
> >         }
> >  
> > -       igt_warn("ran out of dmesg, this shouldn't happen\n");
> > +       igt_warn("Ran out of dmesg, this shouldn't happen. Reason: ");
> > +       if (errno)
> 
> errno is only valid immediately after an error (after a success, the
> value is undefined, often garbage). You just called a few library
> functions and overwrote errno.
> 
> igt_warn("...Reason: %s\n", errno ? strerror(errno) : "EOF");
> 
> (Although I didn't double check nothing untoward happened to upset errno
> before hand, but it looks like we should only get here after getline()
> fails.)

Yeah this part still needs some cleanup. I just wanted some data for
now to see why we ran out of dmesg. "this shouldn't happen" happens
way too often when you test...

I also did notice your suggestion for suppressions.txt and agree with
it. This series needs some serious polishing first, so I'll make that
happen later when everything else works.



-- 
Petri Latvala