[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

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:

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

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"

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]+}}]