[lldb] Move TestDarwinNSLogOutput to PExpectTest and allow checking for missing substrs in PExpectTest

[teemperor]

Summary

TestDarwinNSLogOutput reimplements all the utility functions of the PexpectTestCase. The
test is also randomly failing for me when it tries to tear down the process after LLDB was already
closed.

This patch removes all the custom logic in this test and just uses the PExpectTest equivalents.
The only missing functionality that PExpectTest didn't have was checking for missing substrs
in command output (to test that one can disable the NSLog output), so I extended PExpectTest
for that.

[labath]

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

66–82

I think a better approach would be to just eat the entire output until the next prompt, and them pattern match the output normally. We could even delegate to the "real" expect method to do that part. Something like this (untested) snippet should do it:

self.child.expect('(.*)'+ self.PROMPT)
super(PExpectTest, self).expect(self.child.match.group(1), substrs=substrs, matching=matching)

Another advantage of this would be that we would avoid waiting for the timeout in case the command does not produce the expected output (but it still terminates correctly, so we can match the next prompt).

[labath]

I still like the idea from the inline comment, but mainly clicking request changes to get this off my queue.

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

class PExpectTest(TestBase):
             for cmd in self.setUpCommands():
                 self.child.expect_exact(cmd)
                 self.expect_prompt()
             if executable is not None:
                 self.child.expect_exact("target create")
                 self.child.expect_exact("Current executable set to")
                 self.expect_prompt()
 
-        def expect(self, cmd, substrs=None):
+        def expect(self, cmd, substrs=[], matching=True):
+            """ Run a command and check if the given substrs are in the
+            terminal output that the command produced. If matching is False,
+            then check that the substrs are *not* in the terminal output
+            of the command. """
             self.assertNotIn('\n', cmd)
             self.child.sendline(cmd)
-            if substrs is not None:
+            if matching:
                 for s in substrs:
                     self.child.expect_exact(s)
+            else:
+                for s in substrs:
+                    try:
+                        # If the substring is not in the output we'll reach
+                        # the timeout. Use a shorter timeout than the usual
+                        # one to prevent spending too much time just waiting.
+                        self.child.expect_exact(s, timeout=10)
+                        raise Exception("Found unexpected substr in output: " +
+                                        s + "\n" + str(self.child))
+                    except pexpect.exceptions.TIMEOUT:
+                        # substr not found
+                        pass
+
             self.expect_prompt()
 
         def quit(self, gracefully=True):
             self.child.sendeof()
             self.child.close(force=not gracefully)
             self.child = None
 
         def cursor_forward_escape_seq(self, chars_to_move):
             """
             Returns the escape sequence to move the cursor forward/right
             by a certain amount of characters.
             """
             return b"\x1b\[" + str(chars_to_move).encode("utf-8") + b"C"

lldb/test/API/macosx/nslog/TestDarwinNSLogOutput.py

-"""
-Test DarwinLog "source include debug-level" functionality provided by the
-StructuredDataDarwinLog plugin.
-
-These tests are currently only supported when running against Darwin
-targets.
-"""
-
-
 import lldb
-import platform
-import re
-
 from lldbsuite.test.decorators import *
 from lldbsuite.test.lldbtest import *
-from lldbsuite.test import lldbtest_config
+from lldbsuite.test.lldbpexpect import PExpectTest
 
+class DarwinNSLogOutputTestCase(PExpectTest):
 
-class DarwinNSLogOutputTestCase(TestBase):
-    NO_DEBUG_INFO_TESTCASE = True
     mydir = TestBase.compute_mydir(__file__)
 
-    @skipUnlessDarwin
-    @skipIfRemote   # this test is currently written using lldb commands & assumes running on local system
-
-    def setUp(self):
-        # Call super's setUp().
-        TestBase.setUp(self)
-        self.child = None
-        self.child_prompt = '(lldb) '
-        self.strict_sources = False
-
-        # Source filename.
-        self.source = 'main.m'
-
-        # Output filename.
-        self.exe_name = self.getBuildArtifact("a.out")
-        self.d = {'OBJC_SOURCES': self.source, 'EXE': self.exe_name}
-
-        # Locate breakpoint.
-        self.line = line_number(self.source, '// break here')
-
-    def tearDown(self):
-        # Shut down the process if it's still running.
-        if self.child:
-            self.runCmd('process kill')
-            self.expect_prompt()
-            self.runCmd('quit')
-
-        # Let parent clean up
-        super(DarwinNSLogOutputTestCase, self).tearDown()
-
-    def run_lldb_to_breakpoint(self, exe, source_file, line,
-                               settings_commands=None):
-        # Set self.child_prompt, which is "(lldb) ".
-        prompt = self.child_prompt
-
-        # So that the child gets torn down after the test.
-        import pexpect
-        import sys
-        if sys.version_info.major == 3:
-          self.child = pexpect.spawnu('%s %s %s' % (lldbtest_config.lldbExec,
-                                                    self.lldbOption, exe))
-        else:
-          self.child = pexpect.spawn('%s %s %s' % (lldbtest_config.lldbExec,
-                                                   self.lldbOption, exe))
-        child = self.child
-
-        # Turn on logging for what the child sends back.
-        if self.TraceOn():
-            child.logfile_read = sys.stdout
-
+    def run_before_log(self, launch_args = []):
+        self.build()
         # Disable showing of source lines at our breakpoint.
-        # This is necessary for the logging tests, because the very
+        # This is necessary for the test, because the very
         # text we want to match for output from the running inferior
         # will show up in the source as well.  We don't want the source
         # output to erroneously make a match with our expected output.
-        self.runCmd("settings set stop-line-count-before 0")
-        self.expect_prompt()
-        self.runCmd("settings set stop-line-count-after 0")
-        self.expect_prompt()
-
-        # Run any test-specific settings commands now.
-        if settings_commands is not None:
-            for setting_command in settings_commands:
-                self.runCmd(setting_command)
-                self.expect_prompt()
-
-        # Set the breakpoint, and run to it.
-        child.sendline('breakpoint set -f %s -l %d' % (source_file, line))
-        child.expect_exact(prompt)
-        child.sendline('run')
-        child.expect_exact(prompt)
-
-        # Ensure we stopped at a breakpoint.
-        self.runCmd("thread list")
-        self.expect(re.compile(r"stop reason = .*breakpoint"))
-
-    def runCmd(self, cmd):
-        if self.child:
-            self.child.sendline(cmd)
-
-    def expect_prompt(self, exactly=True):
-        self.expect(self.child_prompt, exactly=exactly)
-
-    def expect(self, pattern, exactly=False, *args, **kwargs):
-        if exactly:
-            return self.child.expect_exact(pattern, *args, **kwargs)
-        return self.child.expect(pattern, *args, **kwargs)
-
-    def do_test(self, expect_regexes=None, settings_commands=None):
-        """ Run a test. """
-        self.build(dictionary=self.d)
-        self.setTearDownCleanup(dictionary=self.d)
-
-        exe = self.getBuildArtifact(self.exe_name)
-        self.run_lldb_to_breakpoint(exe, self.source, self.line,
-                                    settings_commands=settings_commands)
-        self.expect_prompt()
-
-        # Now go.
-        self.runCmd("process continue")
-        self.expect(expect_regexes)
+        launch_args = ["-o", "settings set stop-line-count-before 0",
+                          "-o", "settings set stop-line-count-after 0"] + launch_args
+        self.launch(executable=self.getBuildArtifact("a.out"), extra_args=launch_args)
+
+        self.expect("breakpoint set -p 'About to log'", substrs=["Breakpoint 1", "address ="])
+        self.expect("run", substrs=["stop reason = breakpoint 1"])
+
 
+    # PExpect uses many timeouts internally and doesn't play well
+    # under ASAN on a loaded machine..
+    @skipIfAsan
+    @skipIfEditlineSupportMissing
     def test_nslog_output_is_displayed(self):
         """Test that NSLog() output shows up in the command-line debugger."""
-        self.do_test(expect_regexes=[
-            re.compile(r"(This is a message from NSLog)"),
-            re.compile(r"Process \d+ exited with status")
-        ])
-        self.assertIsNotNone(self.child.match)
-        self.assertGreater(len(self.child.match.groups()), 0)
-        self.assertEqual(
-            "This is a message from NSLog",
-            self.child.match.group(1))
-
+        self.run_before_log()
+        self.expect("continue", substrs=["This is a message from NSLog",
+                                         "exited with status"])
+        self.quit()
+
+    # PExpect uses many timeouts internally and doesn't play well
+    # under ASAN on a loaded machine..
+    @skipIfAsan
+    @skipIfEditlineSupportMissing
+    # IDE_DISABLED_OS_ACTIVITY_DT_MODE available since 10.12.
+    @skipIf(macos_version=["<", "10.12"])
     def test_nslog_output_is_suppressed_with_env_var(self):
         """Test that NSLog() output does not show up with the ignore env var."""
-        # This test will only work properly on macOS 10.12+.  Skip it on earlier versions.
-        # This will require some tweaking on iOS.
-        match = re.match(r"^\d+\.(\d+)", platform.mac_ver()[0])
-        if match is None or int(match.group(1)) < 12:
-            self.skipTest("requires macOS 10.12 or higher")
-
-        self.do_test(
-            expect_regexes=[
-                re.compile(r"(This is a message from NSLog)"),
-                re.compile(r"Process \d+ exited with status")
-            ],
-            settings_commands=[
-                "settings set target.env-vars "
-                "\"IDE_DISABLED_OS_ACTIVITY_DT_MODE=1\""
-            ])
-        self.assertIsNotNone(self.child.match)
-        self.assertEqual(len(self.child.match.groups()), 0)
+        self.run_before_log(launch_args=["-o",
+            "settings set target.env-vars \"IDE_DISABLED_OS_ACTIVITY_DT_MODE=1\""])
+        self.expect("continue", substrs=["This is a message from NSLog"], matching=False)
+        self.quit()