fix command-line LLDB so NSLog messages show up

Changes to the underlying logging infrastructure in Fall 2016 Darwin
OSes were no longer showing up NSLog messages in command-line LLDB.
This change restores that functionality, and adds test cases to
verify the new behavior.

rdar://26732492

llvm-svn: 275472
This commit is contained in:
Todd Fiala 2016-07-14 21:02:45 +00:00
parent 65ca32b83c
commit 4acb65ecee
8 changed files with 390 additions and 0 deletions

View File

@ -438,6 +438,23 @@ public:
void
LongestCommonPrefix (std::string &common_prefix);
//------------------------------------------------------------------
/// Return whether a given environment variable exists.
///
/// This command treats Args like a list of environment variables,
/// as used in ProcessLaunchInfo. It treats each argument as
/// an {env_var_name}={value} or an {env_var_name} entry.
///
/// @param[in] env_var_name
/// Specifies the name of the environment variable to check.
///
/// @return
/// true if the specified env var name exists in the list in
/// either of the above-mentioned formats; otherwise, false.
//------------------------------------------------------------------
bool
ContainsEnvironmentVariable(const char *env_var_name) const;
protected:
//------------------------------------------------------------------
// Classes that inherit from Args can see and modify these

View File

@ -0,0 +1,6 @@
LEVEL = ../../make
OBJC_SOURCES := main.m
LD_EXTRAS = -framework Foundation
include $(LEVEL)/Makefile.rules

View File

@ -0,0 +1,141 @@
"""
Test DarwinLog "source include debug-level" functionality provided by the
StructuredDataDarwinLog plugin.
These tests are currently only supported when running against Darwin
targets.
"""
from __future__ import print_function
import lldb
import os
import pexpect
import re
import sys
from lldbsuite.test import decorators
from lldbsuite.test import lldbtest
from lldbsuite.test import lldbtest_config
@decorators.skipUnlessDarwin
class DarwinNSLogOutputTestCase(lldbtest.TestBase):
NO_DEBUG_INFO_TESTCASE = True
mydir = lldbtest.TestBase.compute_mydir(__file__)
def setUp(self):
# Call super's setUp().
super(DarwinNSLogOutputTestCase, self).setUp()
self.child = None
self.child_prompt = '(lldb) '
self.strict_sources = False
# Source filename.
self.source = 'main.m'
# Output filename.
self.exe_name = 'a.out'
self.d = {'OBJC_SOURCES': self.source, 'EXE': self.exe_name}
# Locate breakpoint.
self.line = lldbtest.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.
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
# 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()
# 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):
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 = os.path.join(os.getcwd(), 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)
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))
def test_nslog_output_is_suppressed_with_env_var(self):
"""Test that NSLog() output does not show up with the ignore env var."""
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)

View File

@ -0,0 +1,139 @@
"""
Base class for DarwinLog tests.
"""
from __future__ import print_function
import lldb
import os
import pexpect
import re
import sys
from lldbsuite.test import decorators
from lldbsuite.test import lldbtest
from lldbsuite.test import lldbtest_config
from lldbsuite.test import lldbutil
class DarwinLogTestBase(lldbtest.TestBase):
NO_DEBUG_INFO_TESTCASE = True
def setUp(self):
# Call super's setUp().
super(DarwinLogTestBase, self).setUp()
self.child = None
self.child_prompt = '(lldb) '
self.strict_sources = False
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.
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
# 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()
# This setting is required to be set to true in order to get LLDB to set
# the environment variable required by libtrace to have it respect our
# 'plugin structured-data darwin-log source enable/disable' settings.
# Without that, libtrace assumes we want all types of messages when
# attaching with a debugger.
setting = "strict-sources " + "true" if self.strict_sources else "false"
self.runCmd(self.expand_darwinlog_settings_set_command(setting))
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(
self.expand_darwinlog_settings_set_command(setting_command))
self.expect_prompt()
# child.expect_exact(prompt)
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"))
# Now we're ready to check if DarwinLog is available.
if not self.darwin_log_available():
self.skip("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")
@classmethod
def expand_darwinlog_command(cls, command):
return "plugin structured-data darwin-log " + command
@classmethod
def expand_darwinlog_settings_set_command(cls, command):
return "settings set plugin.structured-data.darwin-log." + command
def do_test(self, logging_setup_commands, 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)
exe = os.path.join(os.getcwd(), self.exe_name)
self.run_lldb_to_breakpoint(exe, self.source, self.line,
settings_commands=settings_commands)
self.expect_prompt()
# Run each of the logging setup commands.
for setup_command in logging_setup_commands:
self.runCmd(self.expand_darwinlog_command(setup_command))
self.expect_prompt()
# Enable logging.
self.runCmd(self.expand_darwinlog_command("enable"))
self.expect_prompt()
# Now go.
self.runCmd("process continue")
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)

View File

@ -0,0 +1,18 @@
//===-- main.m --------------------------------------------------*- C++ -*-===//
//
// The LLVM Compiler Infrastructure
//
// This file is distributed under the University of Illinois Open Source
// License. See LICENSE.TXT for details.
//
//===----------------------------------------------------------------------===//
#include <Foundation/Foundation.h>
int main(int argc, char** argv)
{
printf("About to log\n"); // break here
NSLog(@"This is a message from NSLog");
return 0;
}

View File

@ -1139,6 +1139,47 @@ Args::LongestCommonPrefix (std::string &common_prefix)
}
}
bool
Args::ContainsEnvironmentVariable(const char *env_var_name) const
{
// Validate args.
if (!env_var_name)
return false;
// Check each arg to see if it matches the env var name.
for (size_t i = 0; i < GetArgumentCount(); ++i)
{
// Get the arg value.
const char *argument_value = GetArgumentAtIndex(i);
if (!argument_value)
continue;
// Check if we are the "{env_var_name}={env_var_value}" style.
const char *equal_p = strchr(argument_value, '=');
if (equal_p)
{
if (strncmp(env_var_name, argument_value,
equal_p - argument_value) == 0)
{
// We matched.
return true;
}
}
else
{
// We're a simple {env_var_name}-style entry.
if (strcmp(argument_value, env_var_name) == 0)
{
// We matched.
return true;
}
}
}
// We didn't find a match.
return false;
}
size_t
Args::FindArgumentIndexForOption (Option *long_options, int long_options_index)
{

View File

@ -1695,3 +1695,28 @@ PlatformDarwin::LocateExecutable (const char *basename)
return FileSpec();
}
lldb_private::Error
PlatformDarwin::LaunchProcess(lldb_private::ProcessLaunchInfo &launch_info)
{
// Starting in Fall 2016 OSes, NSLog messages only get mirrored to stderr
// if the OS_ACTIVITY_DT_MODE environment variable is set. (It doesn't
// require any specific value; rather, it just needs to exist).
// We will set it here as long as the IDE_DISABLED_OS_ACTIVITY_DT_MODE flag
// is not set. Xcode makes use of IDE_DISABLED_OS_ACTIVITY_DT_MODE to tell
// LLDB *not* to muck with the OS_ACTIVITY_DT_MODE flag when they
// specifically want it unset.
const char *disable_env_var = "IDE_DISABLED_OS_ACTIVITY_DT_MODE";
auto &env_vars = launch_info.GetEnvironmentEntries();
if (!env_vars.ContainsEnvironmentVariable(disable_env_var))
{
// We want to make sure that OS_ACTIVITY_DT_MODE is set so that
// we get os_log and NSLog messages mirrored to the target process
// stderr.
if (!env_vars.ContainsEnvironmentVariable("OS_ACTIVITY_DT_MODE"))
env_vars.AppendArgument("OS_ACTIVITY_DT_MODE=enable");
}
// Let our parent class do the real launching.
return PlatformPOSIX::LaunchProcess(launch_info);
}

View File

@ -98,6 +98,9 @@ public:
lldb_private::FileSpec
LocateExecutable (const char *basename) override;
lldb_private::Error
LaunchProcess(lldb_private::ProcessLaunchInfo &launch_info) override;
protected:
void
ReadLibdispatchOffsetsAddress (lldb_private::Process *process);