From 836da99af9cbede44b1e619aa182589d025a6113 Mon Sep 17 00:00:00 2001 From: Dan Liew Date: Mon, 8 Apr 2019 22:28:27 +0000 Subject: [PATCH] [asan_symbolize] Use proper logging infrastructure. Summary: The previous logging infrastructure had several problems: * Debugging output was emitted to standard output which is also where the symbolized output would go. Interleaving these two separate bits of information makes inspecting the output difficult and could potentially break tests. * Enabling debugging output requires modifying the script which is not very conveninent. * When debugging it isn't immediately obvious where the output is coming from. This patch uses the Python standard library logging infrastructure which fixes all of the above problems. Logging is controlled using two new options. * `--log-level` - Sets the logging level, default is `info`. * `--log-dest` - Set the logging destination, default is standard error. Some simple test cases for the feature are included. rdar://problem/49476995 Reviewers: kubamracek, yln, samsonov, dvyukov, vitalybuka Subscribers: #sanitizers, llvm-commits Tags: #llvm, #sanitizers Differential Revision: https://reviews.llvm.org/D60343 llvm-svn: 357951 --- .../lib/asan/scripts/asan_symbolize.py | 63 ++++++++++++++----- .../logging_options_in_help.cc | 5 ++ .../asan_symbolize_script/set_log_dest.cc | 3 + .../asan_symbolize_script/set_log_level.cc | 8 +++ 4 files changed, 65 insertions(+), 14 deletions(-) create mode 100644 compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/logging_options_in_help.cc create mode 100644 compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/set_log_dest.cc create mode 100644 compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/set_log_level.cc diff --git a/compiler-rt/lib/asan/scripts/asan_symbolize.py b/compiler-rt/lib/asan/scripts/asan_symbolize.py index 5cb42c656110e..840e901285283 100755 --- a/compiler-rt/lib/asan/scripts/asan_symbolize.py +++ b/compiler-rt/lib/asan/scripts/asan_symbolize.py @@ -9,13 +9,13 @@ import argparse import bisect import getopt +import logging import os import re import subprocess import sys symbolizers = {} -DEBUG = False demangle = False binutils_prefix = None sysroot_path = None @@ -87,8 +87,7 @@ def open_llvm_symbolizer(self): if self.system == 'Darwin': for hint in self.dsym_hints: cmd.append('--dsym-hint=%s' % hint) - if DEBUG: - print(' '.join(cmd)) + logging.debug(' '.join(cmd)) try: result = subprocess.Popen(cmd, stdin=subprocess.PIPE, stdout=subprocess.PIPE, @@ -105,8 +104,7 @@ def symbolize(self, addr, binary, offset): result = [] try: symbolizer_input = '"%s" %s' % (binary, offset) - if DEBUG: - print(symbolizer_input) + logging.debug(symbolizer_input) self.pipe.stdin.write("%s\n" % symbolizer_input) while True: function_name = self.pipe.stdout.readline().rstrip() @@ -151,8 +149,7 @@ def open_addr2line(self): if demangle: cmd += ['--demangle'] cmd += ['-e', self.binary] - if DEBUG: - print(' '.join(cmd)) + logging.debug(' '.join(cmd)) return subprocess.Popen(cmd, stdin=subprocess.PIPE, stdout=subprocess.PIPE, bufsize=0, @@ -221,8 +218,7 @@ def __init__(self, addr, binary, arch): self.open_atos() def open_atos(self): - if DEBUG: - print('atos -o %s -arch %s' % (self.binary, self.arch)) + logging.debug('atos -o %s -arch %s', self.binary, self.arch) cmdline = ['atos', '-o', self.binary, '-arch', self.arch] self.atos = UnbufferedLineConverter(cmdline, close_stderr=True) @@ -240,8 +236,7 @@ def symbolize(self, addr, binary, offset): # A well-formed atos response looks like this: # foo(type1, type2) (in object.name) (filename.cc:80) match = re.match('^(.*) \(in (.*)\) \((.*:\d*)\)$', atos_line) - if DEBUG: - print('atos_line: ', atos_line) + logging.debug('atos_line: %s', atos_line) if match: function_name = match.group(1) function_name = re.sub('\(.*?\)', '', function_name) @@ -454,8 +449,7 @@ def process_line_posix(self, line): match = re.match(stack_trace_line_format, line) if not match: return [self.current_line] - if DEBUG: - print(line) + logging.debug(line) _, frameno_str, addr, binary, offset = match.groups() arch = "" # Arch can be embedded in the filename, e.g.: "libabc.dylib:x86_64h" @@ -479,8 +473,47 @@ def process_line_posix(self, line): symbolized_line = self.symbolize_address(addr, original_binary, offset, arch) return self.get_symbolized_lines(symbolized_line) +def add_logging_args(parser): + parser.add_argument('--log-dest', + default=None, + help='Destination path for script logging (default stderr).', + ) + parser.add_argument('--log-level', + choices=['debug', 'info', 'warning', 'error', 'critical'], + default='info', + help='Log level for script (default: %(default)s).' + ) + +def setup_logging(): + # Set up a parser just for parsing the logging arguments. + # This is necessary because logging should be configured before we + # perform the main argument parsing. + parser = argparse.ArgumentParser(add_help=False) + add_logging_args(parser) + pargs, unparsed_args = parser.parse_known_args() + + log_level = getattr(logging, pargs.log_level.upper()) + if log_level == logging.DEBUG: + log_format = '%(levelname)s: [%(funcName)s() %(filename)s:%(lineno)d] %(message)s' + else: + log_format = '%(levelname)s: %(message)s' + basic_config = { + 'level': log_level, + 'format': log_format + } + log_dest = pargs.log_dest + if log_dest: + basic_config['filename'] = log_dest + logging.basicConfig(**basic_config) + logging.debug('Logging level set to "{}" and directing output to "{}"'.format( + pargs.log_level, + 'stderr' if log_dest is None else log_dest) + ) + return unparsed_args + if __name__ == '__main__': + remaining_args = setup_logging() parser = argparse.ArgumentParser( formatter_class=argparse.RawDescriptionHelpFormatter, description='ASan symbolization script', @@ -500,7 +533,9 @@ def process_line_posix(self, line): help='set log file name to parse, default is stdin') parser.add_argument('--force-system-symbolizer', action='store_true', help='don\'t use llvm-symbolizer') - args = parser.parse_args() + # Add logging arguments so that `--help` shows them. + add_logging_args(parser) + args = parser.parse_args(remaining_args) if args.path_to_cut: fix_filename_patterns = args.path_to_cut if args.demangle: diff --git a/compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/logging_options_in_help.cc b/compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/logging_options_in_help.cc new file mode 100644 index 0000000000000..b3df1cb354b15 --- /dev/null +++ b/compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/logging_options_in_help.cc @@ -0,0 +1,5 @@ +// RUN: %asan_symbolize --help > %t_help_output.txt +// RUN: FileCheck %s -input-file=%t_help_output.txt +// CHECK: optional arguments: +// CHECK: --log-dest +// CHECK: --log-level diff --git a/compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/set_log_dest.cc b/compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/set_log_dest.cc new file mode 100644 index 0000000000000..f2c309808747e --- /dev/null +++ b/compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/set_log_dest.cc @@ -0,0 +1,3 @@ +// RUN: %asan_symbolize --log-level debug --log-dest %t_debug_log_output.txt --help +// RUN: FileCheck %s -input-file=%t_debug_log_output.txt -check-prefix=DEBUG-CHECK +// DEBUG-CHECK: DEBUG: [setup_logging() asan_symbolize.py:{{[0-9]+}}] Logging level set to "debug" diff --git a/compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/set_log_level.cc b/compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/set_log_level.cc new file mode 100644 index 0000000000000..b30fd6ec3cc43 --- /dev/null +++ b/compiler-rt/test/asan/TestCases/Posix/asan_symbolize_script/set_log_level.cc @@ -0,0 +1,8 @@ +// RUN: %asan_symbolize --log-level debug --help 2> %t_debug_log_output.txt +// RUN: FileCheck %s -input-file=%t_debug_log_output.txt -check-prefix=DEBUG-CHECK +// DEBUG-CHECK: DEBUG: [setup_logging() asan_symbolize.py:{{[0-9]+}}] Logging level set to "debug" +// +// FileCheck doesn't like empty files so add stdout too. +// RUN: %asan_symbolize --log-level info --help > %t_info_log_output.txt 2>&1 +// RUN: FileCheck %s -input-file=%t_info_log_output.txt -check-prefix=INFO-CHECK +// INFO-CHECK-NOT: DEBUG: [setup_logging() asan_symbolize.py:{{[0-9]+}}]