| """ |
| Base class for DarwinLog tests. |
| """ |
| |
| # System imports |
| from __future__ import print_function |
| |
| import json |
| import platform |
| import re |
| import sys |
| import threading |
| |
| |
| # lldb imports |
| import lldb |
| from lldb import SBProcess, SBTarget |
| |
| from lldbsuite.test import decorators |
| from lldbsuite.test import lldbtest |
| from lldbsuite.test import lldbtest_config |
| from lldbsuite.test import lldbutil |
| |
| |
| def expand_darwinlog_command(command): |
| return "plugin structured-data darwin-log " + command |
| |
| |
| def expand_darwinlog_settings_set_command(command): |
| return "settings set plugin.structured-data.darwin-log." + command |
| |
| |
| class DarwinLogTestBase(lldbtest.TestBase): |
| """Base class for DarwinLog test cases that are pexpect-based.""" |
| NO_DEBUG_INFO_TESTCASE = True |
| |
| CONTINUE_REGEX = re.compile(r"Process \d+ resuming") |
| |
| def setUp(self): |
| # Call super's setUp(). |
| super(DarwinLogTestBase, self).setUp() |
| |
| # Until other systems support this, exit |
| # early if we're not macOS version 10.12 |
| # or greater. |
| version = platform.mac_ver()[0].split('.') |
| if ((int(version[0]) == 10) and (int(version[1]) < 12) or |
| (int(version[0]) < 10)): |
| self.skipTest("DarwinLog tests currently require macOS 10.12+") |
| return |
| |
| self.child = None |
| self.child_prompt = '(lldb) ' |
| self.strict_sources = False |
| self.enable_process_monitor_logging = False |
| |
| def run_lldb_to_breakpoint(self, exe, source_file, line, |
| enable_command=None, settings_commands=None): |
| |
| import pexpect |
| # Set self.child_prompt, which is "(lldb) ". |
| prompt = self.child_prompt |
| |
| # So that the child gets torn down after the test. |
| 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 |
| |
| if self.enable_process_monitor_logging: |
| if platform.system() == 'Darwin': |
| self.runCmd( |
| "settings set target.process.extra-startup-command " |
| "QSetLogging:bitmask=LOG_DARWIN_LOG;") |
| self.expect_prompt() |
| |
| # Run the enable command if we have one. |
| if enable_command is not None: |
| self.runCmd(enable_command) |
| self.expect_prompt() |
| |
| # Disable showing of source lines at our breakpoint. |
| # This is necessary for the logging tests, 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() |
| |
| # While we're debugging, turn on packet logging. |
| self.runCmd("log enable -f /tmp/packets.log gdb-remote packets") |
| self.expect_prompt() |
| |
| # Prevent mirroring of NSLog/os_log content to stderr. We want log |
| # messages to come exclusively through our log channel. |
| self.runCmd( |
| "settings set target.env-vars IDE_DISABLED_OS_ACTIVITY_DT_MODE=1") |
| self.expect_prompt() |
| |
| # Run any darwin-log settings commands now, before we enable logging. |
| if settings_commands is not None: |
| for setting_command in settings_commands: |
| self.runCmd( |
| expand_darwinlog_settings_set_command(setting_command)) |
| self.expect_prompt() |
| |
| # Set breakpoint right before the os_log() macros. We don't |
| # set it on the os_log*() calls because these are a number of |
| # nested-scoped calls that will cause the debugger to stop |
| # multiple times on the same line. That is difficult to match |
| # os_log() content by since it is non-deterministic what the |
| # ordering between stops and log lines will be. This is why |
| # we stop before, and then have the process run in a sleep |
| # afterwards, so we get the log messages while the target |
| # process is "running" (sleeping). |
| child.sendline('breakpoint set -f %s -l %d' % (source_file, line)) |
| child.expect_exact(prompt) |
| |
| # Now run to the breakpoint that we just set. |
| 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")) |
| |
| # Now we're ready to check if DarwinLog is available. |
| if not self.darwin_log_available(): |
| self.skipTest("DarwinLog not available") |
| |
| def runCmd(self, cmd): |
| 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 darwin_log_available(self): |
| self.runCmd("plugin structured-data darwin-log status") |
| self.expect(re.compile(r"Availability: ([\S]+)")) |
| return self.child.match is not None and ( |
| self.child.match.group(1) == "available") |
| |
| def do_test(self, enable_options, expect_regexes=None, |
| settings_commands=None): |
| """Test that a single fall-through reject rule rejects all logging.""" |
| self.build(dictionary=self.d) |
| self.setTearDownCleanup(dictionary=self.d) |
| |
| # Build the darwin-log enable command. |
| enable_cmd = expand_darwinlog_command('enable') |
| if enable_options is not None and len(enable_options) > 0: |
| enable_cmd += ' ' + ' '.join(enable_options) |
| |
| exe = self.getBuildArtifact(self.exe_name) |
| self.run_lldb_to_breakpoint(exe, self.source, self.line, |
| enable_command=enable_cmd, |
| settings_commands=settings_commands) |
| self.expect_prompt() |
| |
| # Now go. |
| self.runCmd("process continue") |
| self.expect(self.CONTINUE_REGEX) |
| |
| if expect_regexes is None: |
| # Expect matching a log line or program exit. |
| # Test methods determine which ones are valid. |
| expect_regexes = ( |
| [re.compile(r"source-log-([^-]+)-(\S+)"), |
| re.compile(r"exited with status") |
| ]) |
| self.expect(expect_regexes) |
| |
| |
| def remove_add_mode_entry(log_entries): |
| """libtrace creates an "Add Mode:..." message when logging is enabled. |
| Strip this out of results since our test subjects don't create it.""" |
| return [entry for entry in log_entries |
| if "message" in entry and |
| not entry["message"].startswith("Add Mode:")] |
| |
| |
| class DarwinLogEventBasedTestBase(lldbtest.TestBase): |
| """Base class for event-based DarwinLog tests.""" |
| NO_DEBUG_INFO_TESTCASE = True |
| |
| class EventListenerThread(threading.Thread): |
| |
| def __init__(self, listener, process, trace_on, max_entry_count): |
| super( |
| DarwinLogEventBasedTestBase.EventListenerThread, |
| self).__init__() |
| self.process = process |
| self.listener = listener |
| self.trace_on = trace_on |
| self.max_entry_count = max_entry_count |
| self.exception = None |
| self.structured_data_event_count = 0 |
| self.wait_seconds = 2 |
| self.max_timeout_count = 4 |
| self.log_entries = [] |
| |
| def handle_structured_data_event(self, event): |
| structured_data = SBProcess.GetStructuredDataFromEvent(event) |
| if not structured_data.IsValid(): |
| if self.trace_on: |
| print("invalid structured data") |
| return |
| |
| # Track that we received a valid structured data event. |
| self.structured_data_event_count += 1 |
| |
| # Grab the individual log entries from the JSON. |
| stream = lldb.SBStream() |
| structured_data.GetAsJSON(stream) |
| dict = json.loads(stream.GetData()) |
| self.log_entries.extend(dict["events"]) |
| if self.trace_on: |
| print("Structured data (raw):", stream.GetData()) |
| |
| # Print the pretty-printed version. |
| if self.trace_on: |
| stream.Clear() |
| structured_data.PrettyPrint(stream) |
| print("Structured data (pretty print):", |
| stream.GetData()) |
| |
| def done(self, timeout_count): |
| """Returns True when we're done listening for events.""" |
| # See if we should consider the number of events retrieved. |
| if self.max_entry_count is not None: |
| if len(self.log_entries) >= self.max_entry_count: |
| # We've received the max threshold of events expected, |
| # we can exit here. |
| if self.trace_on: |
| print("Event listener thread exiting due to max " |
| "expected log entry count being reached.") |
| return True |
| |
| # If our event timeout count has exceeded our maximum timeout count, |
| # we're done. |
| if timeout_count >= self.max_timeout_count: |
| if self.trace_on: |
| print("Event listener thread exiting due to max number of " |
| "WaitForEvent() timeouts being reached.") |
| return True |
| |
| # If our process is dead, we're done. |
| if not self.process.is_alive: |
| if self.trace_on: |
| print("Event listener thread exiting due to test inferior " |
| "exiting.") |
| return True |
| |
| # We're not done. |
| return False |
| |
| def run(self): |
| event = lldb.SBEvent() |
| try: |
| timeout_count = 0 |
| |
| # Wait up to 4 times for the event to arrive. |
| while not self.done(timeout_count): |
| if self.trace_on: |
| print("Calling wait for event...") |
| if self.listener.WaitForEvent(self.wait_seconds, event): |
| while event.IsValid(): |
| # Check if it's a process event. |
| if SBProcess.EventIsStructuredDataEvent(event): |
| self.handle_structured_data_event(event) |
| else: |
| if self.trace_on: |
| print("ignoring unexpected event:", |
| lldbutil.get_description(event)) |
| # Grab the next event, if there is one. |
| event.Clear() |
| if not self.listener.GetNextEvent(event): |
| if self.trace_on: |
| print("listener has no more events " |
| "available at this time") |
| else: |
| if self.trace_on: |
| print("timeout occurred waiting for event...") |
| timeout_count += 1 |
| self.listener.Clear() |
| except Exception as e: |
| self.exception = e |
| |
| def setUp(self): |
| # Call super's setUp(). |
| super(DarwinLogEventBasedTestBase, self).setUp() |
| |
| # Until other systems support this, exit |
| # early if we're not macOS version 10.12 |
| # or greater. |
| version = platform.mac_ver()[0].split('.') |
| if ((int(version[0]) == 10) and (int(version[1]) < 12) or |
| (int(version[0]) < 10)): |
| self.skipTest("DarwinLog tests currently require macOS 10.12+") |
| return |
| |
| # Source filename. |
| self.source = 'main.c' |
| |
| # Output filename. |
| self.exe_name = 'a.out' |
| self.d = {'C_SOURCES': self.source, 'EXE': self.exe_name} |
| |
| # Locate breakpoint. |
| self.line = lldbtest.line_number(self.source, '// break here') |
| |
| # Enable debugserver logging of the darwin log collection |
| # mechanism. |
| self.runCmd("settings set target.process.extra-startup-command " |
| "QSetLogging:bitmask=LOG_DARWIN_LOG;") |
| |
| def darwin_log_available(self): |
| match = self.match("plugin structured-data darwin-log status", |
| patterns=[r"Availability: ([\S]+)"]) |
| return match is not None and (match.group(1) == "available") |
| |
| def do_test(self, enable_options, settings_commands=None, |
| run_enable_after_breakpoint=False, max_entry_count=None): |
| """Runs the test inferior, returning collected events. |
| |
| This method runs the test inferior to the first breakpoint hit. |
| It then adds a listener for structured data events, and collects |
| all events from that point forward until end of execution of the |
| test inferior. It then returns those events. |
| |
| @return |
| A list of structured data events received, in the order they |
| were received. |
| """ |
| self.build(dictionary=self.d) |
| self.setTearDownCleanup(dictionary=self.d) |
| |
| exe = self.getBuildArtifact(self.exe_name) |
| |
| # Create a target by the debugger. |
| target = self.dbg.CreateTarget(exe) |
| self.assertTrue(target, lldbtest.VALID_TARGET) |
| |
| # Run the darwin-log settings commands. |
| if settings_commands is not None: |
| for setting_command in settings_commands: |
| self.runCmd( |
| expand_darwinlog_settings_set_command(setting_command)) |
| |
| # Build the darwin-log enable command. |
| enable_cmd = expand_darwinlog_command("enable") |
| if enable_options is not None and len(enable_options) > 0: |
| enable_cmd += ' ' + ' '.join(enable_options) |
| |
| # Run the darwin-log enable command now if we are not supposed |
| # to do it at the first breakpoint. This tests the start-up |
| # code, which has the benefit of being able to set os_log-related |
| # environment variables. |
| if not run_enable_after_breakpoint: |
| self.runCmd(enable_cmd) |
| |
| # Create the breakpoint. |
| breakpoint = target.BreakpointCreateByLocation(self.source, self.line) |
| self.assertIsNotNone(breakpoint) |
| self.assertTrue(breakpoint.IsValid()) |
| self.assertEqual(1, breakpoint.GetNumLocations(), |
| "Should have found one breakpoint") |
| |
| # Enable packet logging. |
| # self.runCmd("log enable -f /tmp/packets.log gdb-remote packets") |
| # self.runCmd("log enable lldb process") |
| |
| # Launch the process - doesn't stop at entry. |
| process = target.LaunchSimple(None, None, self.getBuildDir()) |
| self.assertIsNotNone(process, lldbtest.PROCESS_IS_VALID) |
| |
| # Keep track of whether we're tracing output. |
| trace_on = self.TraceOn() |
| |
| # Get the next thread that stops. |
| from lldbsuite.test.lldbutil import get_stopped_thread |
| thread = get_stopped_thread(process, lldb.eStopReasonBreakpoint) |
| |
| self.assertIsNotNone(thread, "There should be a thread stopped " |
| "due to breakpoint") |
| |
| # The process should be stopped at this point. |
| self.expect("process status", lldbtest.PROCESS_STOPPED, |
| patterns=['Process .* stopped']) |
| |
| # The stop reason of the thread should be breakpoint. |
| self.expect("thread list", lldbtest.STOPPED_DUE_TO_BREAKPOINT, |
| substrs=['stopped', 'stop reason = breakpoint']) |
| |
| # And our one and only breakpoint should have been hit. |
| self.assertEquals(breakpoint.GetHitCount(), 1) |
| |
| # Check if DarwinLog is available. This check cannot be done |
| # until after the process has started, as the feature availability |
| # comes through the stub. The stub isn't running until |
| # the target process is running. So this is really the earliest |
| # we can check. |
| if not self.darwin_log_available(): |
| self.skipTest("DarwinLog not available") |
| |
| # Now setup the structured data listener. |
| # |
| # Grab the broadcaster for the process. We'll be attaching our |
| # listener to it. |
| broadcaster = process.GetBroadcaster() |
| self.assertIsNotNone(broadcaster) |
| |
| listener = lldb.SBListener("SBStructuredData listener") |
| self.assertIsNotNone(listener) |
| |
| rc = broadcaster.AddListener( |
| listener, lldb.SBProcess.eBroadcastBitStructuredData) |
| self.assertTrue(rc, "Successfully add listener to process broadcaster") |
| |
| # Start the listening thread to retrieve the events. |
| # Bump up max entry count for the potentially included Add Mode: |
| # entry. |
| if max_entry_count is not None: |
| max_entry_count += 1 |
| event_thread = self.EventListenerThread(listener, process, trace_on, |
| max_entry_count) |
| event_thread.start() |
| |
| # Continue the test inferior. We should get any events after this. |
| process.Continue() |
| |
| # Wait until the event thread terminates. |
| # print("main thread now waiting for event thread to receive events.") |
| event_thread.join() |
| |
| # If the process is still alive, we kill it here. |
| if process.is_alive: |
| process.Kill() |
| |
| # Fail on any exceptions that occurred during event execution. |
| if event_thread.exception is not None: |
| # Re-raise it here so it shows up as a test error. |
| raise event_thread |
| |
| # Return the collected logging events. |
| return remove_add_mode_entry(event_thread.log_entries) |
