""" Base class for DarwinLog tests. """ # System imports from __future__ import print_function import json import os 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 = os.path.join(os.getcwd(), 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 = os.path.join(os.getcwd(), 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, os.getcwd()) 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)