[asan_symbolize] Fix bug where the frame counter was not incremented.

[delcypher]

Summary

This bug occurred when a plug-in requested that a binary not be
symbolized while the script is trying to symbolize a stack frame. In
this case self.frame_no would not be incremented. This would cause
subsequent stack frames that are symbolized to be incorrectly numbered.

To fix this get_symbolized_lines() has been modified to take an
argument that indicates whether the stack frame counter should
incremented. In process_line_posix() get_symbolized_lines(None) is
now used in cases where we don't want to symbolize a line so that we can
keep the frame counter increment in a single function.

A test case is included. The test uses a dummy plugin that always asks
asan_symbolize.py script to not symbolize the first binary that the
script asks about. Prior to the patch this would cause the output to
script to look something like

#0 0x0
#0 0x0 in do_access
#1 0x0 in main

rdar://problem/49476995

[delcypher]

@vitalybuka Thanks for the review!

lib/asan/scripts/asan_symbolize.py

if result is None:
       # Initialize system symbolizer only if other symbolizers failed.
       symbolizers[binary].append_symbolizer(
           SystemSymbolizerFactory(self.system, addr, binary, arch))
       result = symbolizers[binary].symbolize(addr, binary, offset)
     # The system symbolizer must produce some result.
     assert result
     return result
 
-  def get_symbolized_lines(self, symbolized_lines):
+  def get_symbolized_lines(self, symbolized_lines, inc_frame_counter=True):
     if not symbolized_lines:
+      if inc_frame_counter:
+        self.frame_no += 1
       return [self.current_line]
     else:
+      assert inc_frame_counter
       result = []
       for symbolized_frame in symbolized_lines:
         result.append('    #%s %s' % (str(self.frame_no), symbolized_frame.rstrip()))
         self.frame_no += 1
       return result
 
   def process_logfile(self):
     self.frame_no = 0
def process_line_posix(self, line):
     # NOTE: We have to very liberal with symbol
     # names in the regex because it could be an
     # Objective-C or C++ demangled name.
     stack_trace_line_format = (
         '^( *#([0-9]+) *)(0x[0-9a-f]+) *(?:in *.+)? *\((.*)\+(0x[0-9a-f]+)\)')
     match = re.match(stack_trace_line_format, line)
     if not match:
       logging.debug('Line "{}" does not match regex'.format(line))
-      return [self.current_line]
+      # Not a frame line so don't increment the frame counter.
+      return self.get_symbolized_lines(None, inc_frame_counter=False)
     logging.debug(line)
     _, frameno_str, addr, binary, offset = match.groups()
+
     if not self.using_module_map and not os.path.isabs(binary):
       # Do not try to symbolicate if the binary is just the module file name
       # and a module map is unavailable.
       # FIXME(dliew): This is currently necessary for reports on Darwin that are
       # partially symbolicated by `atos`.
-      return [self.current_line]
+      return self.get_symbolized_lines(None)
     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
     binary = self.plugin_proxy.filter_binary_path(binary)
     if binary is None:
       # The binary filter has told us this binary can't be symbolized.
       logging.debug('Skipping symbolication of binary "%s"', original_binary)
-      return [self.current_line]
+      return self.get_symbolized_lines(None)
     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)
 
 class AsanSymbolizerPlugInProxy(object):
   """

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

+// This test case checks for an old bug when using plug-ins that caused
+// the stack numbering to be incorrect.
+
+// RUN: %clangxx_asan -O0 -g %s -o %t
+// RUN: %env_asan_opts=symbolize=0 not %run %t DUMMY_ARG > %t.asan_report 2>&1
+// RUN: %asan_symbolize --log-level debug --log-dest %t_debug_log_output.txt -l %t.asan_report --plugins %S/plugin_wrong_frame_number_bug.py > %t.asan_report_sym
+// RUN: FileCheck --input-file=%t.asan_report_sym %s
+
+#include <stdlib.h>
+
+int* p;
+extern "C" {
+
+void bug() {
+  free(p);
+}
+
+void foo(bool call_bug) {
+  if (call_bug)
+    bug();
+}
+
+// This indirection exists so that the call stack
+// is reliably large enough.
+void do_access_impl() {
+  *p = 42;
+}
+
+void do_access() {
+  do_access_impl();
+}
+
+int main(int argc, char** argv) {
+  p = (int*) malloc(sizeof(p));
+  foo(argc > 1);
+  do_access();
+  free(p);
+  return 0;
+}
+}
+
+// Check that the numbering of the stackframes is correct.
+
+// CHECK: AddressSanitizer: heap-use-after-free
+// CHECK-NEXT: WRITE of size
+// CHECK-NEXT: #0 0x{{[0-9a-fA-F]+}}
+// CHECK-NEXT: #1 0x{{[0-9a-fA-F]+}} in do_access
+// CHECK-NEXT: #2 0x{{[0-9a-fA-F]+}} in main

test/asan/TestCases/Posix/asan_symbolize_script/plugin_wrong_frame_number_bug.py

+import logging
+
+class FailOncePlugin(AsanSymbolizerPlugIn):
+  """
+    This is a simple plug-in that always claims
+    that a binary can't be symbolized on the first
+    call but succeeds for all subsequent calls.
+
+    This plug-in exists to reproduce an old bug
+    in the `asan_symbolize.py` script.
+
+    By failing the first symbolization request
+    we used to cause an early exit in `asan_symbolize.py`
+    that didn't increment the frame counter which
+    caused subsequent symbolization attempts to
+    print the wrong frame number.
+  """
+  def __init__(self):
+    self.should_fail = True
+    pass
+
+  def filter_binary_path(self, path):
+    logging.info('filter_binary_path called in NoOpPlugin')
+    if self.should_fail:
+      logging.info('Doing first fail')
+      self.should_fail = False
+      return None
+    logging.info('Doing succeed')
+    return path
+
+register_plugin(FailOncePlugin())