| Message ID | 1448540273-19233-1-git-send-email-joonas.lahtinen@linux.intel.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
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. 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. > + > + p = strchr(igt_kmsg_dump_buf, ';') + 1; > + while (p - igt_kmsg_dump_buf < nbytes) { > + int c = *p++; > + /* Decode non-printable characters escaped in > + * hex form (\x0f). */ > + if (c == '\\') { > + igt_assert(*p++ == 'x'); > + igt_assert(sscanf(p, "%x", &c) == 1); > + p += 2; > + } > + fputc(c, stderr); > + } > + } while(errno == 0); > + > + if (print && nlines) > + fprintf(stderr, "**** END ****\n"); > + > + if (errno != EAGAIN) > + fprintf(stderr, "Error: Incomplete kmsg!\n"); > + > + close(fd); > + > + if (print) { > + igt_kmsg_capture_fd = -1; > + free(igt_kmsg_dump_buf); > + igt_kmsg_dump_buf = NULL; > + } else { > + igt_kmsg_check_fd = -1; > + } > + > + return nlines; > +} > + > __attribute__((format(printf, 1, 2))) > static void kmsg(const char *format, ...) > #define KERN_EMER "<0>" > @@ -712,8 +825,10 @@ out: > /* install exit handler, to ensure we clean up */ > igt_install_exit_handler(common_exit_handler); > > - if (!test_with_subtests) > + if (!test_with_subtests) { > gettime(&subtest_time); > + _igt_kmsg_reset(); > + } > > for (i = 0; (optind + i) < *argc; i++) > argv[i + 1] = argv[optind + i]; > @@ -832,8 +947,9 @@ bool __igt_run_subtest(const char *subtest_name) > igt_debug("Starting subtest: %s\n", subtest_name); > > _igt_log_buffer_reset(); > - > + _igt_kmsg_reset(); > gettime(&subtest_time); > + > return (in_subtest = subtest_name); > } > > @@ -963,6 +1079,9 @@ void __igt_skip_check(const char *file, const int line, > */ > void igt_success(void) > { > + if (_igt_kmsg_dump(false, LOG_WARNING)) > + _igt_kmsg_dump(true, LOG_DEBUG); > + > succeeded_one = true; > if (in_subtest) > exit_subtest("SUCCESS"); > @@ -1005,6 +1124,11 @@ void igt_fail(int exitcode) > > _igt_log_buffer_dump(); > > + /* Show kmsg if not already shown. */ > + if (_igt_kmsg_dump(true, LOG_DEBUG) < 1) > + fprintf(stderr, "No kmsg.\n"); > + > + > if (in_subtest) { > if (exitcode == IGT_EXIT_TIMEOUT) > exit_subtest("TIMEOUT"); > @@ -1111,7 +1235,6 @@ void igt_exit(void) > exit(IGT_EXIT_INVALID); > } > > - > if (igt_only_list_subtests()) > exit(IGT_EXIT_SUCCESS); > > diff --git a/lib/tests/.gitignore b/lib/tests/.gitignore > index a4f1080..c49c178 100644 > --- a/lib/tests/.gitignore > +++ b/lib/tests/.gitignore > @@ -1,5 +1,6 @@ > # Please keep sorted alphabetically > igt_assert > +igt_capture > igt_fork_helper > igt_invalid_subtest_name > igt_list_only > 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? Cheers, Daniel > @@ -0,0 +1,89 @@ > +/* > + * Copyright © 2015 Intel Corporation > + * > + * Permission is hereby granted, free of charge, to any person obtaining a > + * copy of this software and associated documentation files (the "Software"), > + * to deal in the Software without restriction, including without limitation > + * the rights to use, copy, modify, merge, publish, distribute, sublicense, > + * and/or sell copies of the Software, and to permit persons to whom the > + * Software is furnished to do so, subject to the following conditions: > + * > + * The above copyright notice and this permission notice (including the next > + * paragraph) shall be included in all copies or substantial portions of the > + * Software. > + * > + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR > + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, > + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL > + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER > + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING > + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS > + * IN THE SOFTWARE. > + * > + * Authors: > + * Joonas Lahtinen <joonas.lahtinen@linux.intel.com> > + * > + */ > + > +#include "igt_core.h" > +#include <stdio.h> > +#include <syslog.h> > + > +static FILE* kmsg; > + > +static void > +test_kmsg(bool fail) > +{ > + fprintf(kmsg, "<%d>TEST (KMSG)\n", LOG_WARNING); > + fflush(kmsg); > + if (fail) > + igt_fail(IGT_EXIT_FAILURE); > +} > + > +static void > +test_warn(void) > +{ > + igt_warn("TEST (WARN)\n"); > + igt_fail(IGT_EXIT_FAILURE); > +} > + > +static void > +test_debug(void) > +{ > + igt_debug("TEST (DEBUG)\n"); > + igt_fail(IGT_EXIT_FAILURE); > +} > + > +static void > +test_combined(void) > +{ > + igt_warn("TEST #1 (WARN)\n"); > + fputs("TEST #1\n", kmsg); > + igt_warn("TEST #2 (WARN)\n"); > + fputs("TEST #2\n", kmsg); > + fflush(kmsg); > + igt_fail(IGT_EXIT_FAILURE); > +} > + > +igt_main > +{ > + igt_fixture { > + kmsg = fopen("/dev/kmsg", "w"); > + igt_require(kmsg != NULL); > + } > + > + igt_subtest("kmsg") > + test_kmsg(true); > + igt_subtest("kmsg-success") > + test_kmsg(false); > + igt_subtest("warn") > + test_warn(); > + igt_subtest("debug") > + test_debug(); > + igt_subtest("combined") > + test_combined(); > + > + igt_fixture { > + fclose(kmsg); > + } > +} > -- > 2.4.3 >
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
On Thu, Nov 26, 2015 at 05:00:14PM +0200, Joonas Lahtinen wrote: > 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? Hm right, we do raw printing there since that dumps the igt log - would recurse otherwise. > > 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? One option would be to dump it all with igt_debug() with an IGT_LOG_DOMAIN of "dmesg" right before the (sub)test stops, and before we do the logfile record dumping (in case of failure). With that - You could see it when enabling full debug (fancy version could even dump dmesg in realtime in a separate thread so that dmesg and igt log interleave, that would be really useful). - If the test fails we'll also dump dmesg. Only problem is that if there's lots of dmesg spew the dmesg might flush out all the useful log messages from igt itself. We might need to do the interleaving right away. Aside: IGT_LOG_DOMAIN is kinda meant for testcases, for the library it might be better to use the low-level function: igt_log("dmesg", IGT_LOG_DEBUG, ...); > > > > 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. Oh, totally missed that, sorry. But then looking at the testcase it doesn't seem to do all that much really - there's no tests that e.g. igt_warn does what we expect it too. And we have lots of igt_warn and similar all over the place. Real functional testcase for dmesg would be to inject something into kms and make sure we log it. But that unfortunately requires root to run, so not suitable as a library unit test. -Daniel
On pe, 2015-11-27 at 11:31 +0100, Daniel Vetter wrote: > On Thu, Nov 26, 2015 at 05:00:14PM +0200, Joonas Lahtinen wrote: > > 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: <SNIP> > > > > + 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? > > Hm right, we do raw printing there since that dumps the igt log - > would > recurse otherwise. > > > > 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? > > One option would be to dump it all with igt_debug() with an > IGT_LOG_DOMAIN > of "dmesg" right before the (sub)test stops, and before we do the > logfile > record dumping (in case of failure). With that > - You could see it when enabling full debug (fancy version could even > dump > dmesg in realtime in a separate thread so that dmesg and igt log > interleave, that would be really useful). > - If the test fails we'll also dump dmesg. > I wouldn't push dmesg into igt log, because it's just moving same bytes from one place to another, kernel already buffers the dmesg for us and it doesn't have to be read realtime. The FD's can be thought of as glorified pointers, really. With my now merged monotonic raw patches, we should be able to timestamp each igt_warn and igt_debug call and it can be afterwards interleaved with the kernel messages. But this functionality as is, is already nice, because you don't have to keep track of the kmsg in a separate window when running a single test. Maybe we should decide on how to merge this function, and then add the timestamping and interleaved output. > Only problem is that if there's lots of dmesg spew the dmesg might > flush > out all the useful log messages from igt itself. We might need to do > the > interleaving right away. > > Aside: IGT_LOG_DOMAIN is kinda meant for testcases, for the library > it > might be better to use the low-level function: > > igt_log("dmesg", IGT_LOG_DEBUG, ...); > > > > > > > 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. > > Oh, totally missed that, sorry. But then looking at the testcase it > doesn't seem to do all that much really - there's no tests that e.g. > igt_warn does what we expect it too. And we have lots of igt_warn and > similar all over the place. > > Real functional testcase for dmesg would be to inject something into > kms > and make sure we log it. But that unfortunately requires root to run, > so > not suitable as a library unit test. It currently does inject to dmesg (and thus requires root to run), as well as igt_debug and igt_warn, it's just that the test output needs to be visually inspected by a human being. I could of course add a wrapper that executes the binary and makes sure the test output is what it should. Then it would be a test that is self diagnosing. Regards, Joonas > -Daniel
On Fri, Nov 27, 2015 at 01:46:23PM +0200, Joonas Lahtinen wrote: > On pe, 2015-11-27 at 11:31 +0100, Daniel Vetter wrote: > > On Thu, Nov 26, 2015 at 05:00:14PM +0200, Joonas Lahtinen wrote: > > > 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: > <SNIP> > > > > > + 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? > > > > Hm right, we do raw printing there since that dumps the igt log - > > would > > recurse otherwise. > > > > > > 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? > > > > One option would be to dump it all with igt_debug() with an > > IGT_LOG_DOMAIN > > of "dmesg" right before the (sub)test stops, and before we do the > > logfile > > record dumping (in case of failure). With that > > - You could see it when enabling full debug (fancy version could even > > dump > > dmesg in realtime in a separate thread so that dmesg and igt log > > interleave, that would be really useful). > > - If the test fails we'll also dump dmesg. > > > > I wouldn't push dmesg into igt log, because it's just moving same bytes > from one place to another, kernel already buffers the dmesg for us and > it doesn't have to be read realtime. The FD's can be thought of as > glorified pointers, really. The upside is that the 2 logs get interleaved correctly, which I just so absolutely wanted to have for debugging some feature last week ;-) > With my now merged monotonic raw patches, we should be able to > timestamp each igt_warn and igt_debug call and it can be afterwards > interleaved with the kernel messages. Interleaving afterwards is more work. At least manually. > But this functionality as is, is already nice, because you don't have > to keep track of the kmsg in a separate window when running a single > test. Maybe we should decide on how to merge this function, and then > add the timestamping and interleaved output. Well for the interleaved kmsg capture the design would be entirely different: - in common_init launch a thread which captures kmsg in the background constantly and prints it using igt_debug with debug domain "dmesg" - no need any more for dumping the buffer, core igt logging takes care of that. Same for dumping when the test failed, filtering or anything else. - cleanup of that thread is best done with an igt exit handler. Later on we can follow up with switching between igt_debug and igt_warn depending upon log level. Imo the above integrates much nicer into existing igt infrastructure and has the benefit of giving us interleaving, too. Cheers, Daniel > > > Only problem is that if there's lots of dmesg spew the dmesg might > > flush > > out all the useful log messages from igt itself. We might need to do > > the > > interleaving right away. > > > > Aside: IGT_LOG_DOMAIN is kinda meant for testcases, for the library > > it > > might be better to use the low-level function: > > > > igt_log("dmesg", IGT_LOG_DEBUG, ...); > > > > > > > > > > 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. > > > > Oh, totally missed that, sorry. But then looking at the testcase it > > doesn't seem to do all that much really - there's no tests that e.g. > > igt_warn does what we expect it too. And we have lots of igt_warn and > > similar all over the place. > > > > Real functional testcase for dmesg would be to inject something into > > kms > > and make sure we log it. But that unfortunately requires root to run, > > so > > not suitable as a library unit test. > > It currently does inject to dmesg (and thus requires root to run), as > well as igt_debug and igt_warn, it's just that the test output needs to > be visually inspected by a human being. I could of course add a wrapper > that executes the binary and makes sure the test output is what it > should. Then it would be a test that is self diagnosing. > > Regards, Joonas > > > -Daniel > -- > Joonas Lahtinen > Open Source Technology Center > Intel Corporation >
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"); + + p = strchr(igt_kmsg_dump_buf, ';') + 1; + while (p - igt_kmsg_dump_buf < nbytes) { + int c = *p++; + /* Decode non-printable characters escaped in + * hex form (\x0f). */ + if (c == '\\') { + igt_assert(*p++ == 'x'); + igt_assert(sscanf(p, "%x", &c) == 1); + p += 2; + } + fputc(c, stderr); + } + } while(errno == 0); + + if (print && nlines) + fprintf(stderr, "**** END ****\n"); + + if (errno != EAGAIN) + fprintf(stderr, "Error: Incomplete kmsg!\n"); + + close(fd); + + if (print) { + igt_kmsg_capture_fd = -1; + free(igt_kmsg_dump_buf); + igt_kmsg_dump_buf = NULL; + } else { + igt_kmsg_check_fd = -1; + } + + return nlines; +} + __attribute__((format(printf, 1, 2))) static void kmsg(const char *format, ...) #define KERN_EMER "<0>" @@ -712,8 +825,10 @@ out: /* install exit handler, to ensure we clean up */ igt_install_exit_handler(common_exit_handler); - if (!test_with_subtests) + if (!test_with_subtests) { gettime(&subtest_time); + _igt_kmsg_reset(); + } for (i = 0; (optind + i) < *argc; i++) argv[i + 1] = argv[optind + i]; @@ -832,8 +947,9 @@ bool __igt_run_subtest(const char *subtest_name) igt_debug("Starting subtest: %s\n", subtest_name); _igt_log_buffer_reset(); - + _igt_kmsg_reset(); gettime(&subtest_time); + return (in_subtest = subtest_name); } @@ -963,6 +1079,9 @@ void __igt_skip_check(const char *file, const int line, */ void igt_success(void) { + if (_igt_kmsg_dump(false, LOG_WARNING)) + _igt_kmsg_dump(true, LOG_DEBUG); + succeeded_one = true; if (in_subtest) exit_subtest("SUCCESS"); @@ -1005,6 +1124,11 @@ void igt_fail(int exitcode) _igt_log_buffer_dump(); + /* Show kmsg if not already shown. */ + if (_igt_kmsg_dump(true, LOG_DEBUG) < 1) + fprintf(stderr, "No kmsg.\n"); + + if (in_subtest) { if (exitcode == IGT_EXIT_TIMEOUT) exit_subtest("TIMEOUT"); @@ -1111,7 +1235,6 @@ void igt_exit(void) exit(IGT_EXIT_INVALID); } - if (igt_only_list_subtests()) exit(IGT_EXIT_SUCCESS); diff --git a/lib/tests/.gitignore b/lib/tests/.gitignore index a4f1080..c49c178 100644 --- a/lib/tests/.gitignore +++ b/lib/tests/.gitignore @@ -1,5 +1,6 @@ # Please keep sorted alphabetically igt_assert +igt_capture igt_fork_helper igt_invalid_subtest_name igt_list_only 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 @@ -0,0 +1,89 @@ +/* + * Copyright © 2015 Intel Corporation + * + * Permission is hereby granted, free of charge, to any person obtaining a + * copy of this software and associated documentation files (the "Software"), + * to deal in the Software without restriction, including without limitation + * the rights to use, copy, modify, merge, publish, distribute, sublicense, + * and/or sell copies of the Software, and to permit persons to whom the + * Software is furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice (including the next + * paragraph) shall be included in all copies or substantial portions of the + * Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + * + * Authors: + * Joonas Lahtinen <joonas.lahtinen@linux.intel.com> + * + */ + +#include "igt_core.h" +#include <stdio.h> +#include <syslog.h> + +static FILE* kmsg; + +static void +test_kmsg(bool fail) +{ + fprintf(kmsg, "<%d>TEST (KMSG)\n", LOG_WARNING); + fflush(kmsg); + if (fail) + igt_fail(IGT_EXIT_FAILURE); +} + +static void +test_warn(void) +{ + igt_warn("TEST (WARN)\n"); + igt_fail(IGT_EXIT_FAILURE); +} + +static void +test_debug(void) +{ + igt_debug("TEST (DEBUG)\n"); + igt_fail(IGT_EXIT_FAILURE); +} + +static void +test_combined(void) +{ + igt_warn("TEST #1 (WARN)\n"); + fputs("TEST #1\n", kmsg); + igt_warn("TEST #2 (WARN)\n"); + fputs("TEST #2\n", kmsg); + fflush(kmsg); + igt_fail(IGT_EXIT_FAILURE); +} + +igt_main +{ + igt_fixture { + kmsg = fopen("/dev/kmsg", "w"); + igt_require(kmsg != NULL); + } + + igt_subtest("kmsg") + test_kmsg(true); + igt_subtest("kmsg-success") + test_kmsg(false); + igt_subtest("warn") + test_warn(); + igt_subtest("debug") + test_debug(); + igt_subtest("combined") + test_combined(); + + igt_fixture { + fclose(kmsg); + } +}