Re: [PATCH i-g-t v2 3/4] lib/igt_kmod: add compatibility for KUnit

[Isabella Basso]

Hi, David

> Am 01/09/2022 um 3:37 AM schrieb 'David Gow' via KUnit Development <kunit-dev@xxxxxxxxxxxxxxxx>:
> 
> On Mon, Aug 29, 2022 at 8:10 AM Isabella Basso <isabbasso@xxxxxxxxxx> wrote:
>> 
>> This adds functions for both executing the tests as well as parsing (K)TAP
>> kmsg output, as per the KTAP spec [1].
>> 
>> [1] https://www.kernel.org/doc/html/latest/dev-tools/ktap.html
>> 
>> Signed-off-by: Isabella Basso <isabbasso@xxxxxxxxxx>
>> ---
> 
> Thanks very much for sending these patches out again.
> 
> Alas, I don't have a particularly useful igt setup to test this
> properly, but I've left a couple of notes from trying it on my laptop
> here.

Thanks for the review, it’s much appreciated! If you have the time I’ve left a
note at the bottom with a very simple way to run the tests, but I can also
provide you with a pastebin of the results if you prefer.

> 
>> lib/igt_kmod.c | 290 +++++++++++++++++++++++++++++++++++++++++++++++++
>> lib/igt_kmod.h |   2 +
>> 2 files changed, 292 insertions(+)
>> 
>> diff --git a/lib/igt_kmod.c b/lib/igt_kmod.c
>> index 97cac7f5..93cdfcc5 100644
>> --- a/lib/igt_kmod.c
>> +++ b/lib/igt_kmod.c
>> @@ -25,6 +25,7 @@
>> #include <signal.h>
>> #include <errno.h>
>> #include <sys/utsname.h>
>> +#include <limits.h>
>> 
>> #include "igt_aux.h"
>> #include "igt_core.h"
>> @@ -32,6 +33,8 @@
>> #include "igt_sysfs.h"
>> #include "igt_taints.h"
>> 
>> +#define BUF_LEN 4096
>> +
>> /**
>>  * SECTION:igt_kmod
>>  * @short_description: Wrappers around libkmod for module loading/unloading
>> @@ -713,6 +716,293 @@ void igt_kselftest_get_tests(struct kmod_module *kmod,
>>        kmod_module_info_free_list(pre);
>> }
>> 
>> +/**
>> + * lookup_value:
>> + * @haystack: the string to search in
>> + * @needle: the string to search for
>> + *
>> + * Returns: the value of the needle in the haystack, or -1 if not found.
>> + */
>> +static long lookup_value(const char *haystack, const char *needle)
>> +{
>> +       const char *needle_rptr;
>> +       char *needle_end;
>> +       long num;
>> +
>> +       needle_rptr = strcasestr(haystack, needle);
>> +
>> +       if (needle_rptr == NULL)
>> +               return -1;
>> +
>> +       /* skip search string and whitespaces after it */
>> +       needle_rptr += strlen(needle);
>> +
>> +       num = strtol(needle_rptr, &needle_end, 10);
>> +
>> +       if (needle_rptr == needle_end)
>> +               return -1;
>> +
>> +       if (num == LONG_MIN || num == LONG_MAX)
>> +               return 0;
>> +
>> +       return num > 0 ? num : 0;
>> +}
>> +
>> +static int find_next_tap_subtest(char *record, char *test_name,
>> +                                bool is_subtest)
>> +{
>> +       const char *name_lookup_str,
>> +             *lend, *version_rptr, *name_rptr;
>> +       long test_count;
>> +
>> +       name_lookup_str = "test: ";
>> +
>> +       version_rptr = strcasestr(record, "TAP version ");
>> +       name_rptr = strcasestr(record, name_lookup_str);
>> +
>> +       /*
>> +        * total test count will almost always appear as 0..N at the beginning
>> +        * of a run, so we use it as indication of a run
>> +        */
>> +       test_count = lookup_value(record, "..");
>> +
>> +       /* no count found, so this is probably not starting a (sub)test */
>> +       if (test_count < 0) {
>> +               if (name_rptr != NULL) {
>> +                       if (test_name[0] == '\0')
>> +                               strncpy(test_name,
>> +                                       name_rptr + strlen(name_lookup_str),
>> +                                       BUF_LEN);
>> +                       else if (strcmp(test_name, name_rptr + strlen(name_lookup_str)) == 0)
>> +                               return 0;
>> +                       else
>> +                               test_name[0] = '\0';
>> +
>> +               }
>> +               return -1;
>> +       }
>> +
>> +       /*
>> +        * "(K)TAP version XX" should be the first line on all (sub)tests as per
>> +        * https://www.kernel.org/doc/html/latest/dev-tools/ktap.html#version-lines
>> +        * but actually isn't, as it currently depends on whoever writes the
>> +        * test to print this info
> 
> FYI: we're really trying to fix cases of "missing version lines",
> largely by making the kunit_test_suites() macro work in more
> circumstances.
> 
> So while it may be worth still handling the case where this is
> missing, I don't think there are any tests in the latest versions of
> the kernel which should have this missing.

I’m not sure if I totally get how these work. Every time I run a KUnit test I
get something like this: https://pastebin.com/7Ff31PMC

As you can see it has been loaded as a module, just like we intend to do it
from IGT, and I see no version lines whatsoever. Am I doing something wrong?

> 
>> +        */
>> +       if (version_rptr == NULL)
>> +               igt_info("Missing test version string\n");
>> +
>> +       if (name_rptr == NULL) {
>> +               /* we have to keep track of the name string, as it might be
>> +                * contained in a line read previously */
>> +               if (test_name[0] == '\0') {
>> +                       igt_info("Missing test name string\n");
>> +
>> +                       if (is_subtest)
>> +                               igt_info("Running %ld subtests...\n", test_count);
>> +                       else
>> +                               igt_info("Running %ld tests...\n", test_count);
>> +               } else {
>> +                       lend = strchrnul(test_name, '\n');
>> +
>> +                       if (*lend == '\0') {
>> +                               if (is_subtest)
>> +                                       igt_info("Executing %ld subtests in: %s\n",
>> +                                                test_count, test_name);
>> +                               else
>> +                                       igt_info("Executing %ld tests in: %s\n",
>> +                                                test_count, test_name);
>> +                               return test_count;
>> +                       }
>> +
>> +                       if (is_subtest)
>> +                               igt_info("Executing %ld subtests in: %.*s\n",
>> +                                        test_count, (int)(lend - test_name),
>> +                                        test_name);
>> +                       else
>> +                               igt_info("Executing %ld tests in: %.*s\n",
>> +                                        test_count, (int)(lend - test_name),
>> +                                        test_name);
>> +                       test_name[0] = '\0';
>> +               }
>> +       } else {
>> +               name_rptr += strlen(name_lookup_str);
>> +               lend = strchrnul(name_rptr, '\n');
>> +               /*
>> +                * as the test count comes after the test name we need not check
>> +                * for a long line again
>> +                */
>> +               if (is_subtest)
>> +                       igt_info("Executing %ld subtests in: %.*s\n",
>> +                                test_count, (int)(lend - name_rptr),
>> +                                name_rptr);
>> +               else
>> +                       igt_info("Executing %ld tests in: %.*s\n",
>> +                                test_count, (int)(lend - name_rptr),
>> +                                name_rptr);
>> +       }
>> +
>> +       return test_count;
>> +}
>> +
>> +static void parse_kmsg_for_tap(const char *lstart, char *lend,
>> +                              int *sublevel, bool *failed_tests)
>> +{
>> +       const char *nok_rptr, *comment_start, *value_parse_start;
>> +
>> +       nok_rptr = strstr(lstart, "not ok ");
>> +       if (nok_rptr != NULL) {
>> +               igt_warn("kmsg> %.*s\n",
>> +                        (int)(lend - lstart), lstart);
>> +               *failed_tests = true;
>> +               return;
>> +       }
>> +
>> +       comment_start = strchrnul(lstart, '#');
>> +
>> +       /* check if we're still in a subtest */
>> +       if (*comment_start != '\0') {
>> +               comment_start++;
>> +               value_parse_start = comment_start;
>> +
>> +               if (lookup_value(value_parse_start, "fail: ") > 0) {
>> +                       igt_warn("kmsg> %.*s\n",
>> +                                (int)(lend - comment_start), comment_start);
>> +                       *failed_tests = true;
>> +                       (*sublevel)--;
>> +                       return;
>> +               }
>> +       }
>> +
>> +       igt_info("kmsg> %.*s\n",
>> +                (int)(lend - lstart), lstart);
>> +}
>> +
>> +static void igt_kunit_subtests(int fd, char *record,
>> +                              int *sublevel, bool *failed_tests)
>> +{
>> +       char test_name[BUF_LEN + 1], *lend;
>> +
>> +       lend = NULL;
>> +       test_name[0] = '\0';
>> +       test_name[BUF_LEN] = '\0';
>> +
>> +       while (*sublevel >= 0) {
>> +               const char *lstart;
>> +               ssize_t r;
>> +
>> +               if (lend != NULL && *lend != '\0')
>> +                       lseek(fd, (int) (lend - record), SEEK_CUR);
>> +
>> +               r = read(fd, record, BUF_LEN);
>> +
>> +               if (r <= 0) {
>> +                       switch (errno) {
>> +                       case EINTR:
>> +                               continue;
>> +                       case EPIPE:
>> +                               igt_warn("kmsg truncated: too many messages. \
>> +                                        You may want to increase log_buf_len \
>> +                                        in your boot options\n");
>> +                               continue;
>> +                       case !EAGAIN:
>> +                               igt_warn("kmsg truncated: unknown error (%m)\n");
>> +                               *sublevel = -1;
>> +                       default:
>> +                               break;
>> +                       }
>> +                       break;
>> +               }
>> +
>> +               lend = strchrnul(record, '\n');
>> +
>> +               /* in case line > 4096 */
>> +               if (*lend == '\0')
>> +                       continue;
>> +
>> +               if (find_next_tap_subtest(record, test_name, *sublevel > 0) != -1)
>> +                       (*sublevel)++;
>> +
>> +               if (*sublevel > 0) {
>> +                       lstart = strchrnul(record, ';');
>> +
>> +                       if (*lstart == '\0') {
>> +                               igt_warn("kmsg truncated: output malformed (%m)\n");
>> +                               igt_fail(IGT_EXIT_FAILURE);
>> +                       }
>> +
>> +                       lstart++;
>> +                       while (isspace(*lstart))
>> +                               lstart++;
>> +
>> +                       parse_kmsg_for_tap(lstart, lend, sublevel, failed_tests);
>> +               }
>> +       }
>> +
>> +       if (*failed_tests || *sublevel < 0)
>> +               igt_fail(IGT_EXIT_FAILURE);
>> +       else
>> +               igt_success();
>> +}
>> +
>> +/**
>> + * igt_kunit:
>> + * @module_name: the name of the module
>> + * @opts: options to load the module
>> + *
>> + * Loads the kunit module, parses its dmesg output, then unloads it
>> + */
>> +void igt_kunit(const char *module_name, const char *opts)
>> +{
>> +       struct igt_ktest tst;
>> +       char record[BUF_LEN + 1];
>> +       bool failed_tests = false;
>> +       int sublevel = 0;
>> +
>> +       record[BUF_LEN] = '\0';
>> +
>> +       /* get normalized module name */
>> +       if (igt_ktest_init(&tst, module_name) != 0) {
>> +               igt_warn("Unable to initialize ktest for %s\n", module_name);
>> +               return;
>> +       }
>> +
>> +       if (igt_ktest_begin(&tst) != 0) {
>> +               igt_warn("Unable to begin ktest for %s\n", module_name);
>> +
>> +               igt_ktest_fini(&tst);
>> +               return;
>> +       }
>> +
>> +       if (tst.kmsg < 0) {
>> +               igt_warn("Could not open /dev/kmsg");
>> +               goto unload;
>> +       }
>> +
>> +       if (lseek(tst.kmsg, 0, SEEK_END)) {
>> +               igt_warn("Could not seek the end of /dev/kmsg");
>> +               goto unload;
>> +       }
>> +
>> +       /* The kunit module is required for running any kunit tests */
>> +       if (igt_kmod_load("kunit", NULL) != 0) {
>> +               igt_warn("Unable to load kunit module\n");
>> +               goto unload;
>> +       }
> 
> Do you want to _require_ KUnit be built as a module, rather than built-in here?

This line is a little misleading because, for our purposes, only the thing to
be tested has to be built as a module, but we can use this function for both
validating a built-in module as well as modprobe-ing it if it's „standalone" (I
tested both cases as well). I’ll change the comment and the warning in v3
to clarify this.

The actual problem would be to unload something that’s built-in, so that’s why
I added a check in the unload function in the previous patch.

> Equally, does this need to mark a failure (or at least "SKIPPED")
> rather than success, in the case it fails.

That’s a good point, will change in v3.

>> +
>> +       if (igt_kmod_load(module_name, opts) != 0) {
>> +               igt_warn("Unable to load %s module\n", module_name);
>> +               goto unload;
>> +       }
> 
> As above, should this record a failure, or skip?

Ack.

>> +
>> +       igt_kunit_subtests(tst.kmsg, record, &sublevel, &failed_tests);
>> +unload:
>> +       igt_kmod_unload("kunit", 0);
> 
> Do you want to unconditionally unload the KUnit module here? It's safe
> (maybe even safer) to leave it loaded between runs of KUnit tests.

That’s a great point. The user should be safe using KUnit as built-in in that
case, but I’ll remove this line as it is unnecessary.

> Equally, how would you handle the case where KUnit is already loaded?

That’s not a problem as pointed out above, kmod handles that without trouble.

>> +
>> +       igt_ktest_end(&tst);
>> +
>> +       igt_ktest_fini(&tst);
>> +}
>> +
>> static int open_parameters(const char *module_name)
>> {
>>        char path[256];
>> diff --git a/lib/igt_kmod.h b/lib/igt_kmod.h
>> index ceb10cd0..737143c1 100644
>> --- a/lib/igt_kmod.h
>> +++ b/lib/igt_kmod.h
>> @@ -45,6 +45,8 @@ int __igt_i915_driver_unload(char **whom);
>> int igt_amdgpu_driver_load(const char *opts);
>> int igt_amdgpu_driver_unload(void);
>> 
>> +void igt_kunit(const char *module_name, const char *opts);
>> +
>> void igt_kselftests(const char *module_name,
>>                    const char *module_options,
>>                    const char *result_option,
>> --
>> 2.37.2
>> 
> 
> Regardless, thanks very much. Hopefully I'll get a chance to play with
> igt a bit more and actually get the tests running. :-)

That shouldn’t be too difficult, when you compile IGT as per the docs you can
just run e.g. `sudo ./build/tests/drm_buddy` and that should do it :).

Cheers,
--
Isabella Basso

> 
> Cheers,
> -- David