[asan_symbolize] Avoid blocking when llvm-symbolizer is installed as addr2line

[arichardson]

Summary

Currently, llvm-symbolizer will print -1 when presented with -1 and not
print a second line. In that case we will block for ever trying to read
the file name. This also happens for non-existent files, in which case GNU
addr2line exits immediate, but llvm-symbolizer does not (see
https://llvm.org/PR42754). While touching these lines, I also added some
more debug logging to help diagnose this and potential future issues.

[arichardson]

Ping? This breaks unit test when building with -DLLVM_INSTALL_BINUTILS_SYMLINKS=ON

[eugenis]

LGTM

[vitalybuka]

Now it breaks http://lab.llvm.org:8011/builders/sanitizer-x86_64-linux/builds/23108/steps/check-asan%20in%20gcc%20build/logs/stdio

FAIL: AddressSanitizer-i386-linux :: TestCases/Posix/asan-symbolize-bad-path.cpp (530 of 1412)
******************** TEST 'AddressSanitizer-i386-linux :: TestCases/Posix/asan-symbolize-bad-path.cpp' FAILED ********************
Script:
--
: 'RUN: at line 3';   echo '#0 0xabcdabcd (/b/sanitizer-x86_64-linux/build/clang_build/projects/compiler-rt/test/asan/I386LinuxConfig/TestCases/Posix/Output/asan-symbolize-bad-path.cpp.tmp/bad/path+0x1234)' | /usr/bin/python /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py  | FileCheck /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/test/asan/TestCases/Posix/asan-symbolize-bad-path.cpp -check-prefix CHECK-BAD-FILE
: 'RUN: at line 8';      /b/sanitizer-x86_64-linux/build/clang_build/./bin/clang  --driver-mode=g++ -fsanitize=address -mno-omit-leaf-frame-pointer -fno-omit-frame-pointer -fno-optimize-sibling-calls -gline-tables-only  -m32  -O0 /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/test/asan/TestCases/Posix/asan-symbolize-bad-path.cpp -o /b/sanitizer-x86_64-linux/build/clang_build/projects/compiler-rt/test/asan/I386LinuxConfig/TestCases/Posix/Output/asan-symbolize-bad-path.cpp.tmp
: 'RUN: at line 9';   echo '#0 0xabcdabcd (/b/sanitizer-x86_64-linux/build/clang_build/projects/compiler-rt/test/asan/I386LinuxConfig/TestCases/Posix/Output/asan-symbolize-bad-path.cpp.tmp+0x0)' | /usr/bin/python /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py  | FileCheck /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/test/asan/TestCases/Posix/asan-symbolize-bad-path.cpp -check-prefix CHECK-BAD-ADDR
--
Exit Code: 2

Command Output (stderr):
--
LLVMSymbolizer: error reading file: No such file or directory
addr2line: '/b/sanitizer-x86_64-linux/build/clang_build/projects/compiler-rt/test/asan/I386LinuxConfig/TestCases/Posix/Output/asan-symbolize-bad-path.cpp.tmp/bad/path': No such file
Traceback (most recent call last):
  File "/b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py", line 1053, in <module>
    loop.process_logfile()
  File "/b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py", line 472, in process_logfile
    processed = self.process_line(line)
  File "/b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py", line 522, in process_line_posix
    symbolized_line = self.symbolize_address(addr, binary, offset, arch)
  File "/b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py", line 451, in symbolize_address
    result = symbolizers[binary].symbolize(addr, binary, offset)
  File "/b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py", line 290, in symbolize
    result = symbolizer.symbolize(addr, binary, offset)
  File "/b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py", line 202, in symbolize
    except BrokenPipeError:
NameError: global name 'BrokenPipeError' is not defined
FileCheck error: '-' is empty.
FileCheck command line:  FileCheck /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/test/asan/TestCases/Posix/asan-symbolize-bad-path.cpp -check-prefix CHECK-BAD-FILE

--

********************
Testing: 0 .. 10.. 20.. 30.. 40.. 50.. 60.. 
FAIL: AddressSanitizer-x86_64-linux :: TestCases/Posix/asan-symbolize-bad-path.cpp (1003 of 1412)
******************** TEST 'AddressSanitizer-x86_64-linux :: TestCases/Posix/asan-symbolize-bad-path.cpp' FAILED ********************
Script:
--
: 'RUN: at line 3';   echo '#0 0xabcdabcd (/b/sanitizer-x86_64-linux/build/clang_build/projects/compiler-rt/test/asan/X86_64LinuxConfig/TestCases/Posix/Output/asan-symbolize-bad-path.cpp.tmp/bad/path+0x1234)' | /usr/bin/python /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py  | FileCheck /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/test/asan/TestCases/Posix/asan-symbolize-bad-path.cpp -check-prefix CHECK-BAD-FILE
: 'RUN: at line 8';      /b/sanitizer-x86_64-linux/build/clang_build/./bin/clang  --driver-mode=g++ -fsanitize=address -mno-omit-leaf-frame-pointer -fno-omit-frame-pointer -fno-optimize-sibling-calls -gline-tables-only  -m64  -O0 /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/test/asan/TestCases/Posix/asan-symbolize-bad-path.cpp -o /b/sanitizer-x86_64-linux/build/clang_build/projects/compiler-rt/test/asan/X86_64LinuxConfig/TestCases/Posix/Output/asan-symbolize-bad-path.cpp.tmp
: 'RUN: at line 9';   echo '#0 0xabcdabcd (/b/sanitizer-x86_64-linux/build/clang_build/projects/compiler-rt/test/asan/X86_64LinuxConfig/TestCases/Posix/Output/asan-symbolize-bad-path.cpp.tmp+0x0)' | /usr/bin/python /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/lib/asan/scripts/asan_symbolize.py  | FileCheck /b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/test/asan/TestCases/Posix/asan-symbolize-bad-path.cpp -check-prefix CHECK-BAD-ADDR
--
Exit Code: 1

Command Output (stderr):
--
LLVMSymbolizer: error reading file: No such file or directory
addr2line: '/b/sanitizer-x86_64-linux/build/clang_build/projects/compiler-rt/test/asan/X86_64LinuxConfig/TestCases/Posix/Output/asan-symbolize-bad-path.cpp.tmp/bad/path': No such file
/b/sanitizer-x86_64-linux/build/llvm/projects/compiler-rt/test/asan/TestCases/Posix/asan-symbolize-bad-path.cpp:4:20: error: CHECK-BAD-FILE: expected string not found in input
// CHECK-BAD-FILE: #0 0xabcdabcd in ?? ??:0
                   ^
<stdin>:1:2: note: scanning from here
 #0 0xabcdabcd in
 ^

--

********************
Testing: 0 .. 10.. 20.. 30.. 40.. 50.. 60.. 70.. 80.. 90.. 
Testing Time: 27.72s
********************
Failing Tests (2):
    AddressSanitizer-i386-linux :: TestCases/Posix/asan-symbolize-bad-path.cpp
    AddressSanitizer-x86_64-linux :: TestCases/Posix/asan-symbolize-bad-path.cpp

  Expected Passes    : 1055
  Expected Failures  : 2
  Unsupported Tests  : 353
  Unexpected Failures: 2

[vitalybuka]

compiler-rt/trunk/lib/asan/scripts/asan_symbolize.py

202

Probably

except socket.error as e:
    if e.errno == errno.EPIPE:

[arichardson]

In D65322#1646254, @vitalybuka wrote:

Now it breaks http://lab.llvm.org:8011/builders/sanitizer-x86_64-linux/builds/23108/steps/check-asan%20in%20gcc%20build/logs/stdio

I believe I fixed this problem in https://reviews.llvm.org/rL369929

It seems like address %t+0x0 is valid on that builder. Maybe it defaults to -pie. Should be fixable by using an address that is more likely to be invalid.

[vitalybuka]

In D65322#1646427, @arichardson wrote:

In D65322#1646254, @vitalybuka wrote:

Now it breaks http://lab.llvm.org:8011/builders/sanitizer-x86_64-linux/builds/23108/steps/check-asan%20in%20gcc%20build/logs/stdio

I believe I fixed this problem in https://reviews.llvm.org/rL369929

It seems like address %t+0x0 is valid on that builder. Maybe it defaults to -pie. Should be fixable by using an address that is more likely to be invalid.

But it's still a problem in python code which is not going to work on on python 2.7
https://llvm.org/docs/GettingStarted.html promise 2.7 support

[arichardson]

In D65322#1646435, @vitalybuka wrote:

In D65322#1646427, @arichardson wrote:

In D65322#1646254, @vitalybuka wrote:

Now it breaks http://lab.llvm.org:8011/builders/sanitizer-x86_64-linux/builds/23108/steps/check-asan%20in%20gcc%20build/logs/stdio

I believe I fixed this problem in https://reviews.llvm.org/rL369929

It seems like address %t+0x0 is valid on that builder. Maybe it defaults to -pie. Should be fixable by using an address that is more likely to be invalid.

But it's still a problem in python code which is not going to work on on python 2.7

I ran all tests with python 2.7 so I have no idea why it worked. Seems like I never triggered the bad path. Will fix to be python2.7 compatible asap.

[vitalybuka]

thanks!

compiler-rt/trunk/lib/asan/scripts/asan_symbolize.py

 import argparse
 import bisect
 import getopt
 import logging
 import os
 import re
 import subprocess
 import sys
+from distutils.spawn import find_executable
 
 symbolizers = {}
 demangle = False
 binutils_prefix = None
 fix_filename_patterns = None
 logfile = sys.stdin
 allow_system_symbolizer = True
 force_system_symbolizer = False
def __init__(self, binary):
     self.binary = binary
     self.pipe = self.open_addr2line()
     self.output_terminator = -1
 
   def open_addr2line(self):
     addr2line_tool = 'addr2line'
     if binutils_prefix:
       addr2line_tool = binutils_prefix + addr2line_tool
+    logging.debug('addr2line binary is %s' % find_executable(addr2line_tool))
     cmd = [addr2line_tool, '-fi']
     if demangle:
       cmd += ['--demangle']
     cmd += ['-e', self.binary]
     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:
       return None
     lines = []
     try:
       self.pipe.stdin.write("%s\n" % offset)
       self.pipe.stdin.write("%s\n" % self.output_terminator)
       is_first_frame = True
       while True:
         function_name = self.pipe.stdout.readline().rstrip()
+        logging.debug("read function_name='%s' from addr2line" % function_name)
+        # If llvm-symbolizer is installed as addr2line, older versions of
+        # llvm-symbolizer will print -1 when presented with -1 and not print
+        # a second line. In that case we will block for ever trying to read the
+        # file name. This also happens for non-existent files, in which case GNU
+        # addr2line exits immediate, but llvm-symbolizer does not (see
+        # https://llvm.org/PR42754).
+        if function_name == '-1':
+          logging.debug("got function '-1' -> no more input")
+          break
         file_name = self.pipe.stdout.readline().rstrip()
+        logging.debug("read file_name='%s' from addr2line" % file_name)
         if is_first_frame:
           is_first_frame = False
-        elif function_name in ['', '??']:
-          assert file_name == function_name
+        elif function_name == '??':
+          assert file_name == '??:0', file_name
+          logging.debug("got function '??' -> no more input")
+          break
+        elif not function_name:
+          assert not file_name, file_name
+          logging.debug("got empty function name -> no more input")
           break
         lines.append((function_name, file_name));
-    except Exception:
+    except BrokenPipeError:
+      logging.debug("got broken pipe, addr2line returncode=%d" % self.pipe.poll())
+      lines.append(('??', '??:0'))
+    except Exception as e:
+      logging.debug("got unknown exception communicating with addr2line", exc_info=e)
       lines.append(('??', '??:0'))
     return ['%s in %s %s' % (addr, function, fix_filename(file)) for (function, file) in lines]
 
 class UnbufferedLineConverter(object):
   """
   Wrap a child process that responds to each line of input with one line of
   output.  Uses pty to trick the child into providing unbuffered output.
   """

compiler-rt/trunk/test/asan/TestCases/Posix/asan-symbolize-bad-path.cpp

 // Test that asan_symbolize does not hang when provided with an non-existing
 // path.
-// RUN: echo '#0 0xabcdabcd (%t/bad/path+0x1234)' | %asan_symbolize | FileCheck %s
-// CHECK: #0 0xabcdabcd
+// RUN: echo '#0 0xabcdabcd (%t/bad/path+0x1234)' | %asan_symbolize | FileCheck %s -check-prefix CHECK-BAD-FILE
+// CHECK-BAD-FILE: #0 0xabcdabcd in ?? ??:0
+// CHECK-BAD-FILE-EMPTY:
+
+// Also test that asan_symbolize doesn't assert on an invalid address with a valid file:
+// RUN: %clangxx_asan -O0 %s -o %t
+// RUN: echo '#0 0xabcdabcd (%t+0x0)' | %asan_symbolize | FileCheck %s -check-prefix CHECK-BAD-ADDR
+// CHECK-BAD-ADDR: #0 0xabcdabcd in ??
+// CHECK-BAD-ADDR-EMPTY:
+
+int main() {
+  return 0;
+}