[asan_symbolize] Use proper logging infrastructure.

[delcypher]

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

[vitalybuka]

lib/asan/scripts/asan_symbolize.py

18

I'd prefer we avoid env variables here
I guess you can use

args, unknown_args = parser.parse_known_args()

to parse args before pluggins just to setup logging
and then parse them again with additional flags.

[delcypher]

lib/asan/scripts/asan_symbolize.py

18

Good point. I hadn't thought of doing it that way. I'll try it.

On a related note the way I was planning on consuming the list of plug-ins to load (future patch) is via an environment variable. The reasons are the same as this patch but also because it's more convenient (e.g. I can just set the environment variable in my shells environment and avoid having to type long commands). Do you also have the same preference for command line arguments here too?

[vitalybuka]

lib/asan/scripts/asan_symbolize.py

18

yes, I would prefer switch there as well
you can achieve same with something like
(export LIST="a,b,c,d" ; echo $LIST)

[delcypher]

• Use command line arguments instead of environment variables
• Add tests

[vitalybuka]

LGTM

test/asan/TestCases/Posix/asan_symbolize_script/logging_options_in_help.cc

3

does lit pickup test in subdir?

[vitalybuka]

Could you please update the summary?

[delcypher]

In D60343#1458611, @vitalybuka wrote:

Could you please update the summary?

Oops. I updated the commit message but forgot to update the phabricator summary. It's fixed now.

[delcypher]

test/asan/TestCases/Posix/asan_symbolize_script/logging_options_in_help.cc

3

Yes. Running lit with --no-execute shows that the tests I added get picked up.

lib/asan/scripts/asan_symbolize.py

 #!/usr/bin/env python
 #===- lib/asan/scripts/asan_symbolize.py -----------------------------------===#
 #
 # Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
 # See https://llvm.org/LICENSE.txt for license information.
 # SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 #
 #===------------------------------------------------------------------------===#
 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
 binary_name_filter = None
 fix_filename_patterns = None
 logfile = sys.stdin
 allow_system_symbolizer = True
 force_system_symbolizer = False
cmd = [self.symbolizer_path,
            '--use-symbol-table=true',
            '--demangle=%s' % demangle,
            '--functions=linkage',
            '--inlining=true',
            '--default-arch=%s' % self.default_arch]
     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,
                                 bufsize=0,
                                 universal_newlines=True)
     except OSError:
       result = None
     return result
 
   def symbolize(self, addr, binary, offset):
     """Overrides Symbolizer.symbolize."""
     if not self.pipe:
       return None
     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()
         if not function_name:
           break
         file_name = self.pipe.stdout.readline().rstrip()
         file_name = fix_filename(file_name)
         if (not function_name.startswith('??') or
class Addr2LineSymbolizer(Symbolizer):
   def open_addr2line(self):
     addr2line_tool = 'addr2line'
     if binutils_prefix:
       addr2line_tool = binutils_prefix + addr2line_tool
     cmd = [addr2line_tool, '-fi']
     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,
                             universal_newlines=True)
 
   def symbolize(self, addr, binary, offset):
     """Overrides Symbolizer.symbolize."""
     if self.binary != binary:

 class DarwinSymbolizer(Symbolizer):
   def __init__(self, addr, binary, arch):
     super(DarwinSymbolizer, self).__init__()
     self.binary = binary
     self.arch = 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)
 
   def symbolize(self, addr, binary, offset):
     """Overrides Symbolizer.symbolize."""
     if self.binary != binary:
       return None
     if not os.path.exists(binary):
       # If the binary doesn't exist atos will exit which will lead to IOError
       # exceptions being raised later on so just don't try to symbolize.
       return ['{} ({}:{}+{})'.format(addr, binary, self.arch, offset)]
     atos_line = self.atos.convert('0x%x' % int(offset, 16))
     while "got symbolicator for" in atos_line:
       atos_line = self.atos.readline()
     # 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)
       file_name = fix_filename(match.group(3))
       return ['%s in %s %s' % (addr, function_name, file_name)]
     else:
       return ['%s in %s' % (addr, atos_line)]
 
class SymbolizationLoop(object):
   def process_line_posix(self, line):
     self.current_line = line.rstrip()
     #0 0x7f6e35cf2e45  (/blah/foo.so+0x11fe45)
     stack_trace_line_format = (
         '^( *#([0-9]+) *)(0x[0-9a-f]+) *\((.*)\+(0x[0-9a-f]+)\)')
     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"
     colon_pos = binary.rfind(":")
     if colon_pos != -1:
       maybe_arch = binary[colon_pos+1:]
       if is_valid_arch(maybe_arch):
         arch = maybe_arch
         binary = binary[0:colon_pos]
     if arch == "":
       arch = guess_arch(addr)
     if frameno_str == '0':
       # Assume that frame #0 is the first frame of new stack trace.
       self.frame_no = 0
     original_binary = binary
     if self.binary_name_filter:
       binary = self.binary_name_filter(binary)
     symbolized_line = self.symbolize_address(addr, binary, offset, arch)
     if not symbolized_line:
       if original_binary != binary:
         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',
       epilog='Example of use:\n'
              'asan_symbolize.py -c "$HOME/opt/cross/bin/arm-linux-gnueabi-" '
              '-s "$HOME/SymbolFiles" < asan.log')
   parser.add_argument('path_to_cut', nargs='*',
                       help='pattern to be cut from the result file path ')
   parser.add_argument('-d','--demangle', action='store_true',
                       help='demangle function names')
   parser.add_argument('-s', metavar='SYSROOT',
                       help='set path to sysroot for sanitized binaries')
   parser.add_argument('-c', metavar='CROSS_COMPILE',
                       help='set prefix for binutils')
   parser.add_argument('-l','--logfile', default=sys.stdin,
                       type=argparse.FileType('r'),
                       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:
     demangle = True
   if args.s:
     binary_name_filter = sysroot_path_filter
     sysroot_path = args.s
   if args.c:

test/asan/TestCases/Posix/asan_symbolize_script/logging_options_in_help.cc

+// 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

test/asan/TestCases/Posix/asan_symbolize_script/set_log_dest.cc

+// 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"

test/asan/TestCases/Posix/asan_symbolize_script/set_log_level.cc

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