Avoid duplicate error reports / suppressions when UI test reports are...

tools/valgrind/memcheck_analyze.py

 #!/usr/bin/python
 # Copyright (c) 2010 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 # memcheck_analyze.py
 
 ''' Given a valgrind XML file, parses errors and uniques them.'''
 
 import gdb_helper
 
 import logging
 import optparse
 import os
 import re
 import subprocess
 import sys
 import time
 from xml.dom.minidom import parse
 from xml.parsers.expat import ExpatError
 
 import common
 
 # Global symbol table (yuck)
 TheAddressTable = None
 
-# Contains the time when the we started analyzing the first log file.
-# This variable is used to skip incomplete logs after some timeout.
-# TODO(timurrrr): Currently, this needs to be a global variable
-# because analyzer can be called multiple times (e.g. ui_tests)
-# unless we re-factor the analyze system to avoid creating multiple analyzers.
-AnalyzeStartTime = None
-
-# Max time to wait for memcheck logs to complete.
-LOG_COMPLETION_TIMEOUT = 180.0
-
 # These are functions (using C++ mangled names) that we look for in stack
 # traces. We don't show stack frames while pretty printing when they are below
 # any of the following:
 _TOP_OF_STACK_POINTS = [
   # Don't show our testing framework.
   "testing::Test::Run()",
   # Also don't show the internals of libc/pthread.
   "start_thread"
 ]
 
@@ skipping 165 matching lines @@
         self._backtraces.append([description, frames])
         description = None
         stack = None
         frames = None
       elif node.localName == "suppression":
         self._suppression = getCDATAOf(node, "rawtext");
 
   def __str__(self):
     ''' Pretty print the type and backtrace(s) of this specific error,
         including suppression (which is just a mangled backtrace).'''
-    output = self._kind + "\n"
+    output = ""
     if (self._commandline):
       output += self._commandline + "\n"
 
+    output += self._kind + "\n"
     for backtrace in self._backtraces:
       output += backtrace[0] + "\n"
       filter = subprocess.Popen("c++filt -n", stdin=subprocess.PIPE,
                                 stdout=subprocess.PIPE,
                                 stderr=subprocess.STDOUT,
                                 shell=True,
                                 close_fds=True)
       buf = ""
       for frame in backtrace[1]:
         buf +=  (frame[FUNCTION_NAME] or frame[INSTRUCTION_POINTER]) + "\n"
@@ skipping 12 matching lines @@
                                              frame[INSTRUCTION_POINTER])
            if foo[0] != None:
              output += (" (" + foo[0] + ":" + foo[1] + ")")
         elif frame[SRC_FILE_DIR] != "":
           output += (" (" + frame[SRC_FILE_DIR] + "/" + frame[SRC_FILE_NAME] +
                      ":" + frame[SRC_LINE] + ")")
         else:
           output += " (" + frame[OBJECT_FILE] + ")"
         output += "\n"
 
-      # TODO(dank): stop synthesizing suppressions once everyone has
-      # valgrind-3.5 and we can rely on xml
-      if (self._suppression == None):
-        output += "Suppression:\n"
-        for frame in backtrace[1]:
-          output += "  fun:" + (frame[FUNCTION_NAME] or "*") + "\n"
+    assert self._suppression != None, "Your Valgrind doesn't generate " \
+                                      "suppressions - is it too old?"
 
-    if (self._suppression != None):
-      output += "Suppression:"
-      # Widen suppression slightly to make portable between mac and linux
-      supp = self._suppression;
-      supp = supp.replace("fun:_Znwj", "fun:_Znw*")
-      supp = supp.replace("fun:_Znwm", "fun:_Znw*")
-      # Split into lines so we can enforce length limits
-      supplines = supp.split("\n")
+    output += "Suppression (hash=#%X#):" % self.__hash__()
+    # Widen suppression slightly to make portable between mac and linux
+    supp = self._suppression;
+    supp = supp.replace("fun:_Znwj", "fun:_Znw*")
+    supp = supp.replace("fun:_Znwm", "fun:_Znw*")
+    # Split into lines so we can enforce length limits
+    supplines = supp.split("\n")
 
-      # Truncate at line 26 (VG_MAX_SUPP_CALLERS plus 2 for name and type)
-      # or at the first 'boring' caller.
-      # (https://bugs.kde.org/show_bug.cgi?id=199468 proposes raising
-      # VG_MAX_SUPP_CALLERS, but we're probably fine with it as is.)
-      # TODO(dkegel): add more boring callers
-      newlen = 26;
-      try:
-        newlen = min(newlen, supplines.index("   fun:_ZN11MessageLoop3RunEv"))
-      except ValueError:
-        pass
-      if (len(supplines) > newlen):
-        supplines = supplines[0:newlen]
-        supplines.append("}")
+    # Truncate at line 26 (VG_MAX_SUPP_CALLERS plus 2 for name and type)
+    # or at the first 'boring' caller.
+    # (https://bugs.kde.org/show_bug.cgi?id=199468 proposes raising
+    # VG_MAX_SUPP_CALLERS, but we're probably fine with it as is.)
+    # TODO(dkegel): add more boring callers
+    newlen = 26;
+    try:
+      newlen = min(newlen, supplines.index("   fun:_ZN11MessageLoop3RunEv"))
+    except ValueError:
+      pass
+    if (len(supplines) > newlen):
+      supplines = supplines[0:newlen]
+      supplines.append("}")
 
-      output += "\n".join(supplines) + "\n"
+    output += "\n".join(supplines) + "\n"
 
     return output
 
   def UniqueString(self):
     ''' String to use for object identity. Don't print this, use str(obj)
     instead.'''
     rep = self._kind + " "
     for backtrace in self._backtraces:
       for frame in backtrace[1]:
         rep += frame[FUNCTION_NAME]
@@ skipping 14 matching lines @@
   f.seek(0)
   while True:
     line = f.readline()
     if line == "":
       return False
     if '</valgrindoutput>' in line:
       # valgrind often has garbage after </valgrindoutput> upon crash
       f.truncate()
       return True
 
-class MemcheckAnalyze:
+class MemcheckAnalyzer:
   ''' Given a set of Valgrind XML files, parse all the errors out of them,
   unique them and output the results.'''
 
   SANITY_TEST_SUPPRESSIONS_LINUX = {
       "Memcheck sanity test 01 (memory leak).": 1,
       "Memcheck sanity test 02 (malloc/read left).": 1,
       "Memcheck sanity test 03 (malloc/read right).": 1,
       "Memcheck sanity test 04 (malloc/write left).": 1,
       "Memcheck sanity test 05 (malloc/write right).": 1,
       "Memcheck sanity test 06 (new/read left).": 1,
@@ skipping 13 matching lines @@
       "Memcheck sanity test 06 (new/read left).": 1,
       "Memcheck sanity test 07 (new/read right).": 1,
       "Memcheck sanity test 10 (write after free).": 1,
       "Memcheck sanity test 11 (write after delete).": 1,
       "bug_49253 Memcheck sanity test 12 (array deleted without []) on Mac.": 1,
       "bug_49253 Memcheck sanity test 13 (single element deleted with []) on Mac.": 1,
       "bug_49253 Memcheck sanity test 04 (malloc/write left) or Memcheck sanity test 05 (malloc/write right) on Mac.": 2,
       "bug_49253 Memcheck sanity test 08 (new/write left) or Memcheck sanity test 09 (new/write right) on Mac.": 2,
   }
 
-  def __init__(self, source_dir, files, show_all_leaks=False, use_gdb=False):
-    '''Reads in a set of files.
+  # Max time to wait for memcheck logs to complete.
+  LOG_COMPLETION_TIMEOUT = 180.0
+
+  def __init__(self, source_dir, show_all_leaks=False, use_gdb=False):
+    '''Create a parser for Memcheck logs.
 
     Args:
       source_dir: Path to top of source tree for this build
+      show_all_leaks: Whether to show even less important leaks
+      use_gdb: Whether to use gdb to resolve source filenames and line numbers
+               in the report stacktraces
+    '''
+    self._source_dir = source_dir
+    self._show_all_leaks = show_all_leaks
+    self._use_gdb = use_gdb
+
+    # Contains the set of unique errors
+    self._errors = set()
+
+    # Contains the time when the we started analyzing the first log file.
+    # This variable is used to skip incomplete logs after some timeout.
+    self._analyze_start_time = None
+
+
+  def Report(self, files, check_sanity=False):
+    '''Reads in a set of files and prints Memcheck report.
+
+    Args:
       files: A list of filenames.
-      show_all_leaks: whether to show even less important leaks
+      check_sanity: if true, search for SANITY_TEST_SUPPRESSIONS
     '''
-
     # Beyond the detailed errors parsed by ValgrindError above,
     # the xml file contain records describing suppressions that were used:
     # <suppcounts>
     #  <pair>
     #    <count>28</count>
     #    <name>pango_font_leak_todo</name>
     #  </pair>
     #  <pair>
     #    <count>378</count>
     #    <name>bug_13243</name>
     #  </pair>
     # </suppcounts
     # Collect these and print them at the end.
     #
     # With our patch for https://bugs.kde.org/show_bug.cgi?id=205000 in,
     # the file also includes records of the form
     # <load_obj><obj>/usr/lib/libgcc_s.1.dylib</obj><ip>0x27000</ip></load_obj>
     # giving the filename and load address of each binary that was mapped
     # into the process.
 
     global TheAddressTable
-    if use_gdb:
+    if self._use_gdb:
       TheAddressTable = gdb_helper.AddressTable()
-    self._errors = set()
-    self._suppcounts = {}
+    else:
+      TheAddressTable = None
+    cur_report_errors = set()
+    suppcounts = {}
     badfiles = set()
 
-    global AnalyzeStartTime
-    if AnalyzeStartTime == None:
-      AnalyzeStartTime = time.time()
-    self._parse_failed = False
+    if self._analyze_start_time == None:
+      self._analyze_start_time = time.time()
+    start_time = self._analyze_start_time
+
+    parse_failed = False
     for file in files:
       # Wait up to three minutes for valgrind to finish writing all files,
       # but after that, just skip incomplete files and warn.
       f = open(file, "r+")
       pid = re.match(".*\.([0-9]+)$", file)
       if pid:
         pid = pid.groups()[0]
       found = False
       running = True
       firstrun = True
       origsize = os.path.getsize(file)
       while (running and not found and
              (firstrun or
-              ((time.time() - AnalyzeStartTime) < LOG_COMPLETION_TIMEOUT))):
+              ((time.time() - start_time) < self.LOG_COMPLETION_TIMEOUT))):
         firstrun = False
         f.seek(0)
         if pid:
           # Make sure the process is still running so we don't wait for
           # 3 minutes if it was killed. See http://crbug.com/17453
           ps_out = subprocess.Popen("ps p %s" % pid, shell=True,
                                     stdout=subprocess.PIPE).stdout
           if ps_out.readlines() < 2:
             running = False
         found = find_and_truncate(f)
         if not running and not found:
           logging.warn("Valgrind process PID = %s is not running but "
                        "its XML log has not been finished correctly." % pid)
         if running and not found:
           time.sleep(1)
       f.close()
       if not found:
         badfiles.add(file)
       else:
         newsize = os.path.getsize(file)
         if origsize > newsize+1:
           logging.warn(str(origsize - newsize) +
                        " bytes of junk were after </valgrindoutput> in %s!" %
                        file)
         try:
           parsed_file = parse(file);
         except ExpatError, e:
-          self._parse_failed = True
+          parse_failed = True
           logging.warn("could not parse %s: %s" % (file, e))
           lineno = e.lineno - 1
           context_lines = 5
           context_start = max(0, lineno - context_lines)
           context_end = lineno + context_lines + 1
           context_file = open(file, "r")
           for i in range(0, context_start):
             context_file.readline()
           for i in range(context_start, context_end):
             context_data = context_file.readline().rstrip()
@@ skipping 15 matching lines @@
         for node in preamble.getElementsByTagName("line"):
           if node.localName == "line":
             for x in node.childNodes:
               if x.nodeType == node.TEXT_NODE and "Command" in x.data:
                 commandline = x.data
                 break
 
         raw_errors = parsed_file.getElementsByTagName("error")
         for raw_error in raw_errors:
           # Ignore "possible" leaks for now by default.
-          if (show_all_leaks or
+          if (self._show_all_leaks or
               getTextOf(raw_error, "kind") != "Leak_PossiblyLost"):
-            error = ValgrindError(source_dir, raw_error, commandline)
-            self._errors.add(error)
+            error = ValgrindError(self._source_dir, raw_error, commandline)
+            if error not in cur_report_errors:
+              # We haven't seen such errors doing this report yet...
+              if error in self._errors:
+                # ... but we saw it in earlier reports, e.g. previous UI test
+                cur_report_errors.add("This error was already printed "
+                                      "in some other test, see 'hash=#%X#'" % \
+                                      error.__hash__())
+              else:
+                # ... and we haven't seen it in other tests as well
+                self._errors.add(error)
+                cur_report_errors.add(error)
 
         suppcountlist = parsed_file.getElementsByTagName("suppcounts")
         if len(suppcountlist) > 0:
           suppcountlist = suppcountlist[0]
           for node in suppcountlist.getElementsByTagName("pair"):
             count = getTextOf(node, "count");
             name = getTextOf(node, "name");
-            if name in self._suppcounts:
-              self._suppcounts[name] += int(count)
+            if name in suppcounts:
+              suppcounts[name] += int(count)
             else:
-              self._suppcounts[name] = int(count)
+              suppcounts[name] = int(count)
 
     if len(badfiles) > 0:
       logging.warn("valgrind didn't finish writing %d files?!" % len(badfiles))
       for file in badfiles:
         logging.warn("Last 20 lines of %s :" % file)
         os.system("tail -n 20 '%s' 1>&2" % file)
 
-  def Report(self, check_sanity=False):
-    if self._parse_failed:
+    if parse_failed:
       logging.error("FAIL! Couldn't parse Valgrind output file")
       return -2
 
     is_sane = False
     print "-----------------------------------------------------"
     print "Suppressions used:"
     print "  count name"
 
     if common.IsLinux():
-      remaining_sanity_supp = MemcheckAnalyze.SANITY_TEST_SUPPRESSIONS_LINUX
+      remaining_sanity_supp = MemcheckAnalyzer.SANITY_TEST_SUPPRESSIONS_LINUX
     elif common.IsMac():
-      remaining_sanity_supp = MemcheckAnalyze.SANITY_TEST_SUPPRESSIONS_MAC
+      remaining_sanity_supp = MemcheckAnalyzer.SANITY_TEST_SUPPRESSIONS_MAC
     else:
       remaining_sanity_supp = {}
       if check_sanity:
         logging.warn("No sanity test list for platform %s", sys.platform)
 
-    for (name, count) in sorted(self._suppcounts.items(),
+    for (name, count) in sorted(suppcounts.items(),
                                 key=lambda (k,v): (v,k)):
       print "%7d %s" % (count, name)
       if name in remaining_sanity_supp and remaining_sanity_supp[name] == count:
         del remaining_sanity_supp[name]
     if len(remaining_sanity_supp) == 0:
       is_sane = True
     print "-----------------------------------------------------"
     sys.stdout.flush()
 
     retcode = 0
     if self._errors:
       logging.error("FAIL! There were %s errors: " % len(self._errors))
 
-      global TheAddressTable
       if TheAddressTable != None:
         TheAddressTable.ResolveAll()
 
-      for error in self._errors:
+      for error in cur_report_errors:
         logging.error(error)
 
       retcode = -1
 
     # Report tool's insanity even if there were errors.
     if check_sanity and not is_sane:
       logging.error("FAIL! Sanity check failed!")
       logging.info("The following test errors were not handled: ")
       for (name, count) in sorted(remaining_sanity_supp.items(),
                                   key=lambda (k,v): (v,k)):
         logging.info("%7d %s" % (count, name))
       retcode = -3
 
     if retcode != 0:
       return retcode
 
     logging.info("PASS! No errors found!")
     return 0
 
 def _main():
-  '''For testing only. The MemcheckAnalyze class should be imported instead.'''
+  '''For testing only. The MemcheckAnalyzer class should be imported instead.'''
   retcode = 0
   parser = optparse.OptionParser("usage: %prog [options] <files to analyze>")
   parser.add_option("", "--source_dir",
                     help="path to top of source tree for this build"
                     "(used to normalize source paths in baseline)")
 
   (options, args) = parser.parse_args()
   if len(args) == 0:
     parser.error("no filename specified")
   filenames = args
 
-  analyzer = MemcheckAnalyze(options.source_dir, filenames, use_gdb=True)
-  retcode = analyzer.Report()
+  analyzer = MemcheckAnalyzer(options.source_dir, use_gdb=True)
+  retcode = analyzer.Report(filenames)
 
   sys.exit(retcode)
 
 if __name__ == "__main__":
   _main()