Possible bug in twister gtest harness

[GeekOffTheStreet]

Discussed in #71635

^{Originally posted by GeekOffTheStreet April 17, 2024}
I tried using Twister with the gtest harness and ran into issues with it detecting unit test execution. The behavior for how it parses sample.yaml/testcase.yaml doesn't match what I would expect. I should not that I'm not using pigweed. Consider this simple test case:

#include <gtest/gtest.h>
#include <gmock/gmock.h>
#include <stdio.h>
using namespace testing;

class HelloWorld : public Test {
public:
    HelloWorld() {}
    void SetUp() {}
    void TearDown() {}
};

TEST_F(HelloWorld, foo) {
    EXPECT_TRUE(true);
}

I build that for qemu using:

$ west build -p always -b qemu_leon3--build-dir zephyr-build .
$ /opt/zephyrproject/zephyr/scripts/twister  -vvv -p qemu_leon3 -T ./

If I use the console harness with a sample.yaml resembling:

sample:
  description: Hello World sample, the simplest Zephyr
  name: test hello world
common:
  tags: introduction
  platform_allow: qemu_leon3
  harness: console
  harness_config:
    type: multi_line
    ordered: false
    regex:
      - ".*OK\\s+\\]\\s+HelloWorld.foo.+"

tests:
  HelloWorld.foo:
    tags: introduction

The test works as expected (sample output):

DEBUG   - Determine test cases for test instance: qemu_leon3/HelloWorld.foo
DEBUG   - Determine test cases for test suite: HelloWorld.foo
DEBUG   - Test instance qemu_leon3/HelloWorld.foo already has 1 cases.
DEBUG   - run test: qemu_leon3/HelloWorld.foo
DEBUG   - Reset instance status from 'passed' to None before run.
DEBUG   - Spawning QEMUHandler Thread for qemu_leon3/HelloWorld.foo
DEBUG   - Running qemu_leon3/HelloWorld.foo (qemu)
DEBUG   - Spawning QEMUHandler Thread for qemu_leon3/HelloWorld.foo
DEBUG   - QEMU (232776): [==========] Running 1 test from 1 test case.
DEBUG   - QEMU (232776): [----------] Global test environment set-up.
DEBUG   - QEMU (232776): [----------] 1 test from HelloWorld
DEBUG   - QEMU (232776): [ RUN      ] HelloWorld.foo
DEBUG   - QEMU (232776): [       OK ] HelloWorld.foo (0 ms)
DEBUG   - HARNESS:Console:EXPECTED(1/1):'.*OK\s+\]\s+HelloWorld.foo.+'
DEBUG   - QEMU (232776): [----------] 1 test from HelloWorld (0 ms total)
DEBUG   - QEMU (232776): 
DEBUG   - QEMU (232776): [----------] Global test environment tear-down
DEBUG   - QEMU (232776): [==========] 1 test from 1 test case ran. (10 ms total)
DEBUG   - QEMU (232776): [  PASSED  ] 1 test.
DEBUG   - QEMU (232776): *** Booting Zephyr OS build zephyr-v3.5.0-2466-g654a74ecb7d6 ***
DEBUG   - QEMU (232776) complete (passed) after 2.050739288330078 seconds
DEBUG   - No timeout, return code from QEMU (None): 0
DEBUG   - return code from QEMU (None): 0
DEBUG   - run status: qemu_leon3/HelloWorld.foo passed
INFO    - 1/1 qemu_leon3                HelloWorld.foo                                     PASSED (qemu 2.051s)

INFO    - 1 test scenarios (1 test instances) selected, 0 configurations skipped (0 by static filter, 0 at runtime).

If I try to use the gtest harness:

sample:
  description: Hello World sample, the simplest Zephyr
  name: test hello world
common:
  tags: introduction
  platform_allow: qemu_leon3
  harness: gtest
tests:
  HelloWorld.foo:
    tags: introduction

The runner tries to match HelloWorld.foo.HelloWorld.foo instead of just HelloWorld.foo and fails:

DEBUG   - Determine test cases for test instance: qemu_leon3/HelloWorld.foo
DEBUG   - Determine test cases for test suite: HelloWorld.foo
DEBUG   - Test instance qemu_leon3/HelloWorld.foo already has 1 cases.
DEBUG   - run test: qemu_leon3/HelloWorld.foo
DEBUG   - Reset instance status from 'passed' to None before run.
DEBUG   - Spawning QEMUHandler Thread for qemu_leon3/HelloWorld.foo
DEBUG   - Running qemu_leon3/HelloWorld.foo (qemu)
DEBUG   - Spawning QEMUHandler Thread for qemu_leon3/HelloWorld.foo
DEBUG   - QEMU (234555): [==========] Running 1 test from 1 test case.
DEBUG   - QEMU (234555): [----------] Global test environment set-up.
DEBUG   - QEMU (234555): [----------] 1 test from HelloWorld
DEBUG   - QEMU (234555): [ RUN      ] HelloWorld.foo
DEBUG   - Could not find a matching testcase for HelloWorld.foo.HelloWorld.foo
DEBUG   - QEMU (234555): [       OK ] HelloWorld.foo (0 ms)
Exception in thread qemu_leon3/HelloWorld.foo:
Traceback (most recent call last):
  File "/usr/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.10/threading.py", line 953, in run
    self._target(*self._args, **self._kwargs)
  File "/opt/zephyrproject/zephyr/scripts/pylib/twister/twisterlib/handlers.py", line 902, in _thread
    harness.handle(line)
  File "/opt/zephyrproject/zephyr/scripts/pylib/twister/twisterlib/harness.py", line 573, in handle
    tc is not None and tc == self.tc
AssertionError: gTest error, mismatched tests. Expected HelloWorld.foo.HelloWorld.foo but got None
DEBUG   - return code from QEMU (None): 2
DEBUG   - run status: qemu_leon3/HelloWorld.foo failed
INFO    - 1/1 qemu_leon3                HelloWorld.foo                                      FAILED Timeout (qemu)

I didn't see an obvious way to alter the matching behavior.

@yperess

[github-actions]

Hi @GeekOffTheStreet! We appreciate you submitting your first issue for our open-source project. 🌟

Even though I'm a bot, I can assure you that the whole community is genuinely grateful for your time and effort. 🤖💙

[yperess]

Thank you, I'll take a look this week.

[vChavezB]

I am also experiencing a similar issue with twister. In my case I want to integrate CPPUTest so I had a look at the Gtest Harness. This brought me to this issue.

As far as I understand the problem is that each test case name obtained dynamically from the std output of the Harness (Gtest in this case), is created by the format {test case id}.{test suite}.{test case}. This is done specifically here:

zephyr/scripts/pylib/twister/twisterlib/harness.py

Line 582 in 4d0a8c1

name = "{}.{}.{}".format(self.id, suite_name, test_start_match.group("test_name"))

I think that is the reason we get from harness handle from Gtest a created instance with name HelloWorld.foo.HelloWorld.foo.

What happen is the following:

1. Test suite Hello world with test case Foo runs and prints

   [ RUN ] HelloWorld.foo

2. The Test instance module does not find the instance and prints

   DEBUG - Could not find a matching testcase for HelloWorld.foo.HelloWorld.foo

   This happens due to the format I mentioned at the beginning. This in turn creates a new test instance called HelloWorld.foo.HelloWorld.foo

3. Test suite Hello world with test case Foo finishes and prints

   [OK ] HelloWorld.foo (0 ms)

4. The GTest Harness detects that a test finished here:

   zephyr/scripts/pylib/twister/twisterlib/harness.py

   Line 613 in 4d0a8c1

   state, name = self._check_result(non_ansi_line)

5. Now here is the important part. The refex pattern TEST_PASS_PATTERN I think is wrong. If I test it with regex101.com this is the result I get https://regex101.com/r/Uj6EYf/1

   

   As you see the string representation of the test case will be HelloWorld.foo.HelloWorld.foo (0 ms) instead of the expected HelloWorld.foo.HelloWorld.foo. This in turn returns None

   zephyr/scripts/pylib/twister/twisterlib/testinstance.py

   Lines 159 to 163 in 4d0a8c1

   	def get_case_by_name(self, name):
   	for c in self.testcases:
   	if c.name == name:
   	return c
   	return None

   and makes the assertion fail.

   zephyr/scripts/pylib/twister/twisterlib/harness.py

   Lines 620 to 623 in 4d0a8c1

   	assert (
   	tc is not None and tc == self.tc
   	), "gTest error, mismatched tests. Expected {} but got {}".format(self.tc, tc)

Possible solution

Change the Pass pattern (and similarly the fail pattern as well) to something as

.*\[ OK \] (?P<suite_name>\S+)\.(?P<test_name>\S+) \(\d+ ms\)

https://regex101.com/r/NX5ul9/1

[byteinthewild]

@yperess

I recently stumbled on this issue because I'm seeing the same error
DEBUG - Could not find a matching testcase for HelloWorld.foo.HelloWorld.foo

It looks like the pull request resolved another issue related to test timing being at the end of the gtest output, but did not address the duplicated suite and test name that vChavezB described above. Am I missing something else here?

To elaborate:

If I create a testcase.yaml that looks like:

tests:
  HelloWorld.foo:
    tags: foo

and have a gtest like:

TEST(HelloWorld, foo) {
    EXPECT_TRUE(true);
}

I see that the testcases property in testinstance.py is populated with 2 entries:

HelloWorld.foo
HelloWorld.foo.HelloWorld.foo

which the gtest harness will match HelloWorld.foo.HelloWorld.foo and then report HelloWorld.foo failed with a timeout

If I edit harness.py to remove self.id from the name as vChavezB suggested, we hit this assert as it believes the test is duplicate: https://github.com/zephyrproject-rtos/zephyr/blob/main/scripts/pylib/twister/twisterlib/harness.py#L613

Additionally, it looks to me like the FINISHED_PATTERN regex is not correct. Maybe this is from an older version of gtest?
I believe the current output looks like

[==========] 1 tests from 1 test cases ran. (43 ms total)
[  PASSED  ] 1 tests.

and the regex should look something like:

.*\[==========\] \d+ test(s?) from \d+ test (case(s?)|suite(s?)) ran..*

Its still not clear to me if this is just a misconfiguration of testcase.yaml or if the gtest harness is broken. I could use some guidance on what the testcase.yaml for existing gtests should look like.

I'm happy to open a new issue to properly capture this, but wanted to start here since it was relevant to the originally closed issue

[yperess]

@byteinthewild I'm on vacation right now, but I'll try to take a look ASAP

[byteinthewild]

Thank you very much, enjoy your vacation!

[akrenz]

Applying the changes from here: https://github.com/zephyrproject-rtos/zephyr/pull/65430/files fixed the issue for Googletest 1.15.0.

Unfortunately the changes have not been merged into zephyr.

[yperess]

Started working on this, should have it fixed by the end of the week.