[lldb] Improve test failure reporting for expect()

[DavidSpickett]

Summary

This updates the errors reported by expect()
to something like:

Ran command:
"help"

Got output:
Debugger commands:
<...>

Expecting start string: "Debugger commands:" (was found)
Expecting end string: "foo" (was not found)

(see added tests for more examples)

This shows the user exactly what was run,
what checks passed and which failed. Along with
whether that check was supposed to pass.
(including what regex patterns matched)

These lines are also output to the test
trace file, whether the test passes or not.

Note that expect() will still fail at the first failed
check, in line with previous behaviour.

Also I have flipped the wording of the assert
message functions (.*_MSG) to describe failures
not successes. This makes more sense as they are
only shown on assert failures.

[DavidSpickett]

I realise the test is a bit meta so if there might be a better place to put it. It does at least run successfully from the API test dir.

[DavidSpickett]

lldb/packages/Python/lldbsuite/test/lldbtest.py

2459

I've added speech marks around things that are probably on the shorter side. I've found it helps narrow down issues with empty strings or leading/trailing whitespace.

[labath]

I like this. And a big thank-you for writing the tests. We don't usually bother to write self-tests for the test infrastructure, but we definitely should be doing that. The place is slightly weird, but I think it will do for now -- it's easy to move this around if we find a better place for it.

lldb/test/API/assert_messages_test/TestAssertMessages.py

38–39

These two calls always come in pairs, right? Might be nice to make this a single function which gets both the command to run, and the error message it is expected to fail with.

[DavidSpickett]

Combined two functions into one single run command
and check message function.

With some odd kwargs, but I think it helps to be able
to put the expected lines on the end.

[labath]

Awesome.

In D86792#2252243, @DavidSpickett wrote:

Combined two functions into one single run command
and check message function.

With some odd kwargs, but I think it helps to be able
to put the expected lines on the end.

I think that's ok. Another option might be to take the expect argument as a dictionary instead of **kwargs. Something like:

    def assert_expect_fails_with(self, cmd, expect_args, failure_substrs):
        try:
            # This expect should fail
            self.expect(cmd, **expect_args)
        except AssertionError as e:
            # Then check message from previous expect
            self.expect(str(e), exe=False, substrs=failure_substrs)

...
assert_expect_fails_with("foo", dict(endstr="foo"), "...")

lldb/test/API/assert_messages_test/TestAssertMessages.py

82

I'd consider moving the dedent and the listification ([]) operations into the assert_expect_fails_with function.

[DavidSpickett]

• Use settings command so we don't have to substr help's output
• Move list and dedent calls into assert function

[DavidSpickett]

Thanks for the review!

lldb/packages/Python/lldbsuite/test/lldbtest.py

 VALID_VARIABLE = "Got a valid variable"
 
 VARIABLES_DISPLAYED_CORRECTLY = "Variable(s) displayed correctly"
 
 WATCHPOINT_CREATED = "Watchpoint created successfully"
 
 
 def CMD_MSG(str):
-    '''A generic "Command '%s' returns successfully" message generator.'''
-    return "Command '%s' returns successfully" % str
+    '''A generic "Command '%s' did not return successfully" message generator.'''
+    return "Command '%s' did not return successfully" % str
 
 
 def COMPLETION_MSG(str_before, str_after, completions):
-    '''A generic message generator for the completion mechanism.'''
+    '''A generic assertion failed message generator for the completion mechanism.'''
     return ("'%s' successfully completes to '%s', but completions were:\n%s"
            % (str_before, str_after, "\n".join(completions)))
 
 
 def EXP_MSG(str, actual, exe):
     '''A generic "'%s' returned unexpected result" message generator if exe.
     Otherwise, it generates "'%s' does not match expected result" message.'''
 
     return "'%s' %s result, got '%s'" % (
         str, 'returned unexpected' if exe else 'does not match expected', actual.strip())
 
 
 def SETTING_MSG(setting):
-    '''A generic "Value of setting '%s' is correct" message generator.'''
-    return "Value of setting '%s' is correct" % setting
+    '''A generic "Value of setting '%s' is not correct" message generator.'''
+    return "Value of setting '%s' is not correct" % setting
 
 
 def line_number(filename, string_to_match):
     """Helper function to return the line number of the first matched string."""
     with io.open(filename, mode='r', encoding="utf-8") as f:
         for i, line in enumerate(f):
             if line.find(string_to_match) != -1:
                 # Found our match.
def expect(
             # No execution required, just compare str against the golden input.
             if isinstance(str, lldb.SBCommandReturnObject):
                 output = str.GetOutput()
             else:
                 output = str
             with recording(self, trace) as sbuf:
                 print("looking at:", output, file=sbuf)
 
-        # The heading says either "Expecting" or "Not expecting".
-        heading = "Expecting" if matching else "Not expecting"
+        expecting_str = "Expecting" if matching else "Not expecting"
+        def found_str(matched):
+            return "was found" if matched else "was not found"
+
+        # To be used as assert fail message and/or trace content
+        log_lines = [
+                "{}:".format("Ran command" if exe else "Checking string"),
+                "\"{}\"".format(str),
+                # Space out command and output
+                "",
+        ]
+        if exe:
+            # Newline before output to make large strings more readable
+            log_lines.append("Got output:\n{}".format(output))
 
-        # Start from the startstr, if specified.
-        # If there's no startstr, set the initial state appropriately.
-        matched = output.startswith(startstr) if startstr else (
-            True if matching else False)
+        # Assume that we start matched if we want a match
+        # Meaning if you have no conditions, matching or
+        # not matching will always pass
+        matched = matching
 
+        # We will stop checking on first failure
         if startstr:
-            with recording(self, trace) as sbuf:
-                print("%s start string: %s" % (heading, startstr), file=sbuf)
-                print("Matched" if matched else "Not matched", file=sbuf)
+            matched = output.startswith(startstr)
+            log_lines.append("{} start string: \"{}\" ({})".format(
+                    expecting_str, startstr, found_str(matched)))
 
-        # Look for endstr, if specified.
-        keepgoing = matched if matching else not matched
-        if endstr:
+        if endstr and matched == matching:
             matched = output.endswith(endstr)
-            with recording(self, trace) as sbuf:
-                print("%s end string: %s" % (heading, endstr), file=sbuf)
-                print("Matched" if matched else "Not matched", file=sbuf)
+            log_lines.append("{} end string: \"{}\" ({})".format(
+                    expecting_str, endstr, found_str(matched)))
 
-        # Look for sub strings, if specified.
-        keepgoing = matched if matching else not matched
-        if substrs and keepgoing:
+        if substrs and matched == matching:
             start = 0
             for substr in substrs:
                 index = output[start:].find(substr)
                 start = start + index if ordered and matching else 0
                 matched = index != -1
-                with recording(self, trace) as sbuf:
-                    print("%s sub string: %s" % (heading, substr), file=sbuf)
-                    print("Matched" if matched else "Not matched", file=sbuf)
-                keepgoing = matched if matching else not matched
-                if not keepgoing:
+                log_lines.append("{} sub string: \"{}\" ({})".format(
+                        expecting_str, substr, found_str(matched)))
+
+                if matched != matching:
                     break
 
-        # Search for regular expression patterns, if specified.
-        keepgoing = matched if matching else not matched
-        if patterns and keepgoing:
+        if patterns and matched == matching:
             for pattern in patterns:
-                # Match Objects always have a boolean value of True.
-                matched = bool(re.search(pattern, output))
-                with recording(self, trace) as sbuf:
-                    print("%s pattern: %s" % (heading, pattern), file=sbuf)
-                    print("Matched" if matched else "Not matched", file=sbuf)
-                keepgoing = matched if matching else not matched
-                if not keepgoing:
+                matched = re.search(pattern, output)
+
+                pattern_line = "{} regex pattern: \"{}\" ({}".format(
+                        expecting_str, pattern, found_str(matched))
+                if matched:
+                    pattern_line += ", matched \"{}\"".format(
+                            matched.group(0))
+                pattern_line += ")"
+                log_lines.append(pattern_line)
+
+                # Convert to bool because match objects
+                # are True-ish but != True itself
+                matched = bool(matched)
+                if matched != matching:
                     break
 
-        self.assertTrue(matched if matching else not matched,
-                        msg + "\nCommand output:\n" + EXP_MSG(str, output, exe)
-                        if msg else EXP_MSG(str, output, exe))
+        # If a check failed, add any extra assert message
+        if msg is not None and matched != matching:
+            log_lines.append(msg)
+
+        log_msg = "\n".join(log_lines)
+        with recording(self, trace) as sbuf:
+            print(log_msg, file=sbuf)
+        if matched != matching:
+            self.fail(log_msg)
 
     def expect_expr(
             self,
             expr,
             result_summary=None,
             result_value=None,
             result_type=None,
             result_children=None

lldb/test/API/assert_messages_test/TestAssertMessages.py

+"""
+Test the format of API test suite assert failure messages
+"""
+
+
+import lldb
+import lldbsuite.test.lldbutil as lldbutil
+from lldbsuite.test.lldbtest import *
+from textwrap import dedent
+
+
+class AssertMessagesTestCase(TestBase):
+
+    mydir = TestBase.compute_mydir(__file__)
+    NO_DEBUG_INFO_TESTCASE = True
+
+    def assert_expect_fails_with(self, cmd, failure_substrs=None, **kwargs):
+        # failure_substrs is a keyword arg so you can put them last
+        # assert_expect_fails_with(cmd, <cmd args>, failure_subtrs=<expected lines>)
+        if failure_substrs is None:
+            raise RuntimeError("failure_substrs is required")
+
+        try:
+            # This expect should fail
+            self.expect(cmd, **kwargs)
+        except AssertionError as e:
+            # Then check message from previous expect
+            self.expect(str(e), exe=False, substrs=failure_substrs)
+        else:
+            self.fail("Initial expect should have raised AssertionError!")
+
+    def test_expect(self):
+        """Test format of messages produced by expect(...)"""
+
+        # When an expect passes the messages are sent to the trace
+        # file which we can't access here. So really, these only
+        # check what failures look like, but it *should* be the same
+        # content for the trace log too.
+
+        # Will stop at startstr fail
+        self.assert_expect_fails_with("help",
+            startstr="dog", endstr="cat",
+            failure_substrs=[dedent("""\
+                Ran command:
+                "help"
+
+                Got output:
+                Debugger commands:"""),
+                """Expecting start string: "dog" (was not found)"""])
+
+        # startstr passes, endstr fails
+        # We see both reported
+        self.assert_expect_fails_with("help",
+            startstr="Debugger commands:", endstr="foo",
+            failure_substrs=[dedent("""\
+                Ran command:
+                "help"
+
+                Got output:
+                Debugger commands:"""),
+                """Expecting start string: "Debugger commands:" (was found)""",
+                """Expecting end string: "foo" (was not found)"""])
+
+        # Same thing for substrs, regex patterns ignored because of substr failure
+        # Any substr after the first missing is also ignored
+        self.assert_expect_fails_with("abcdefg",
+            substrs=["abc", "ijk", "xyz"],
+            patterns=["foo", "bar"], exe=False,
+            failure_substrs=[dedent("""\
+                Checking string:
+                "abcdefg"
+
+                Expecting sub string: "abc" (was found)
+                Expecting sub string: "ijk" (was not found)""")])
+
+        # Regex patterns also stop at first failure, subsequent patterns ignored
+        # They are last in the chain so no other check gets skipped
+        # Including the rest of the conditions here to prove they are run and shown
+        self.assert_expect_fails_with("0123456789",
+            startstr="012", endstr="789", substrs=["345", "678"],
+            patterns=["[0-9]+", "[a-f]+", "a|b|c"], exe=False,
+            failure_substrs=[dedent("""\
+                Checking string:
+                "0123456789"
+
+                Expecting start string: "012" (was found)
+                Expecting end string: "789" (was found)
+                Expecting sub string: "345" (was found)
+                Expecting sub string: "678" (was found)
+                Expecting regex pattern: "[0-9]+" (was found, matched "0123456789")
+                Expecting regex pattern: "[a-f]+" (was not found)""")])
+
+        # This time we dont' want matches but we do get them
+        self.assert_expect_fails_with("the quick brown fox",
+            # Note that the second pattern *will* match
+            patterns=["[0-9]+", "fox"], exe=False, matching=False,
+            startstr="cat", endstr="rabbit", substrs=["abc", "def"],
+            failure_substrs=[dedent("""\
+                Checking string:
+                "the quick brown fox"
+
+                Not expecting start string: "cat" (was not found)
+                Not expecting end string: "rabbit" (was not found)
+                Not expecting sub string: "abc" (was not found)
+                Not expecting sub string: "def" (was not found)
+                Not expecting regex pattern: "[0-9]+" (was not found)
+                Not expecting regex pattern: "fox" (was found, matched "fox")""")])
+
+        # Extra assert messages are only printed when we get a failure
+        # So I can't test that from here, just how it looks when it's printed
+        self.assert_expect_fails_with("mouse",
+            startstr="cat", exe=False, msg="Reason for check goes here!",
+            failure_substrs=[dedent("""\
+                Checking string:
+                "mouse"
+
+                Expecting start string: "cat" (was not found)
+                Reason for check goes here!""")])