Roll chromium_revision b032878ebd..e438353b8b (480186:480311)

tools_webrtc/valgrind/memcheck_analyze.py

+#!/usr/bin/env python
+# Copyright (c) 2017 The WebRTC project authors. All Rights Reserved.
+#
+# Use of this source code is governed by a BSD-style license
+# that can be found in the LICENSE file in the root of the source
+# tree. An additional intellectual property rights grant can be found
+# in the file PATENTS.  All contributing project authors may
+# be found in the AUTHORS file in the root of the source tree.
+
+# memcheck_analyze.py
+
+''' Given a valgrind XML file, parses errors and uniques them.'''
+
+import gdb_helper
+
+from collections import defaultdict
+import hashlib
+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
+
+# These are regexps that define functions (using C++ mangled names)
+# we don't want to see in stack traces while pretty printing
+# or generating suppressions.
+# Just stop printing the stack/suppression frames when the current one
+# matches any of these.
+_BORING_CALLERS = common.BoringCallers(mangled=True, use_re_wildcards=True)
+
+def getTextOf(top_node, name):
+  ''' Returns all text in all DOM nodes with a certain |name| that are children
+  of |top_node|.
+  '''
+
+  text = ""
+  for nodes_named in top_node.getElementsByTagName(name):
+    text += "".join([node.data for node in nodes_named.childNodes
+                     if node.nodeType == node.TEXT_NODE])
+  return text
+
+def getCDATAOf(top_node, name):
+  ''' Returns all CDATA in all DOM nodes with a certain |name| that are children
+  of |top_node|.
+  '''
+
+  text = ""
+  for nodes_named in top_node.getElementsByTagName(name):
+    text += "".join([node.data for node in nodes_named.childNodes
+                     if node.nodeType == node.CDATA_SECTION_NODE])
+  if (text == ""):
+    return None
+  return text
+
+def shortenFilePath(source_dir, directory):
+  '''Returns a string with the string prefix |source_dir| removed from
+  |directory|.'''
+  prefixes_to_cut = ["build/src/", "valgrind/coregrind/", "out/Release/../../"]
+
+  if source_dir:
+    prefixes_to_cut.append(source_dir)
+
+  for p in prefixes_to_cut:
+    index = directory.rfind(p)
+    if index != -1:
+      directory = directory[index + len(p):]
+
+  return directory
+
+# Constants that give real names to the abbreviations in valgrind XML output.
+INSTRUCTION_POINTER = "ip"
+OBJECT_FILE = "obj"
+FUNCTION_NAME = "fn"
+SRC_FILE_DIR = "dir"
+SRC_FILE_NAME = "file"
+SRC_LINE = "line"
+
+def gatherFrames(node, source_dir):
+  frames = []
+  for frame in node.getElementsByTagName("frame"):
+    frame_dict = {
+      INSTRUCTION_POINTER : getTextOf(frame, INSTRUCTION_POINTER),
+      OBJECT_FILE         : getTextOf(frame, OBJECT_FILE),
+      FUNCTION_NAME       : getTextOf(frame, FUNCTION_NAME),
+      SRC_FILE_DIR        : shortenFilePath(
+          source_dir, getTextOf(frame, SRC_FILE_DIR)),
+      SRC_FILE_NAME       : getTextOf(frame, SRC_FILE_NAME),
+      SRC_LINE            : getTextOf(frame, SRC_LINE)
+    }
+
+    # Ignore this frame and all the following if it's a "boring" function.
+    enough_frames = False
+    for regexp in _BORING_CALLERS:
+      if re.match("^%s$" % regexp, frame_dict[FUNCTION_NAME]):
+        enough_frames = True
+        break
+    if enough_frames:
+      break
+
+    frames += [frame_dict]
+
+    global TheAddressTable
+    if TheAddressTable != None and frame_dict[SRC_LINE] == "":
+      # Try using gdb
+      TheAddressTable.Add(frame_dict[OBJECT_FILE],
+                          frame_dict[INSTRUCTION_POINTER])
+  return frames
+
+class ValgrindError:
+  ''' Takes a <DOM Element: error> node and reads all the data from it. A
+  ValgrindError is immutable and is hashed on its pretty printed output.
+  '''
+
+  def __init__(self, source_dir, error_node, commandline, testcase):
+    ''' Copies all the relevant information out of the DOM and into object
+    properties.
+
+    Args:
+      error_node: The <error></error> DOM node we're extracting from.
+      source_dir: Prefix that should be stripped from the <dir> node.
+      commandline: The command that was run under valgrind
+      testcase: The test case name, if known.
+    '''
+
+    # Valgrind errors contain one <what><stack> pair, plus an optional
+    # <auxwhat><stack> pair, plus an optional <origin><what><stack></origin>,
+    # plus (since 3.5.0) a <suppression></suppression> pair.
+    # (Origin is nicely enclosed; too bad the other two aren't.)
+    # The most common way to see all three in one report is
+    # a syscall with a parameter that points to uninitialized memory, e.g.
+    # Format:
+    # <error>
+    #   <unique>0x6d</unique>
+    #   <tid>1</tid>
+    #   <kind>SyscallParam</kind>
+    #   <what>Syscall param write(buf) points to uninitialised byte(s)</what>
+    #   <stack>
+    #     <frame>
+    #     ...
+    #     </frame>
+    #   </stack>
+    #   <auxwhat>Address 0x5c9af4f is 7 bytes inside a block of ...</auxwhat>
+    #   <stack>
+    #     <frame>
+    #     ...
+    #     </frame>
+    #   </stack>
+    #   <origin>
+    #   <what>Uninitialised value was created by a heap allocation</what>
+    #   <stack>
+    #     <frame>
+    #     ...
+    #     </frame>
+    #   </stack>
+    #   </origin>
+    #   <suppression>
+    #     <sname>insert_a_suppression_name_here</sname>
+    #     <skind>Memcheck:Param</skind>
+    #     <skaux>write(buf)</skaux>
+    #     <sframe> <fun>__write_nocancel</fun> </sframe>
+    #     ...
+    #     <sframe> <fun>main</fun> </sframe>
+    #     <rawtext>
+    # <![CDATA[
+    # {
+    #    <insert_a_suppression_name_here>
+    #    Memcheck:Param
+    #    write(buf)
+    #    fun:__write_nocancel
+    #    ...
+    #    fun:main
+    # }
+    # ]]>
+    #     </rawtext>
+    #   </suppression>
+    # </error>
+    #
+    # Each frame looks like this:
+    #  <frame>
+    #    <ip>0x83751BC</ip>
+    #    <obj>/data/dkegel/chrome-build/src/out/Release/base_unittests</obj>
+    #    <fn>_ZN7testing8internal12TestInfoImpl7RunTestEPNS_8TestInfoE</fn>
+    #    <dir>/data/dkegel/chrome-build/src/testing/gtest/src</dir>
+    #    <file>gtest-internal-inl.h</file>
+    #    <line>655</line>
+    #  </frame>
+    # although the dir, file, and line elements are missing if there is
+    # no debug info.
+
+    self._kind = getTextOf(error_node, "kind")
+    self._backtraces = []
+    self._suppression = None
+    self._commandline = commandline
+    self._testcase = testcase
+    self._additional = []
+
+    # Iterate through the nodes, parsing <what|auxwhat><stack> pairs.
+    description = None
+    for node in error_node.childNodes:
+      if node.localName == "what" or node.localName == "auxwhat":
+        description = "".join([n.data for n in node.childNodes
+                              if n.nodeType == n.TEXT_NODE])
+      elif node.localName == "xwhat":
+        description = getTextOf(node, "text")
+      elif node.localName == "stack":
+        assert description
+        self._backtraces.append([description, gatherFrames(node, source_dir)])
+        description = None
+      elif node.localName == "origin":
+        description = getTextOf(node, "what")
+        stack = node.getElementsByTagName("stack")[0]
+        frames = gatherFrames(stack, source_dir)
+        self._backtraces.append([description, frames])
+        description = None
+        stack = None
+        frames = None
+      elif description and node.localName != None:
+        # The lastest description has no stack, e.g. "Address 0x28 is unknown"
+        self._additional.append(description)
+        description = None
+
+      if 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 = ""
+    output += "\n" # Make sure the ### is at the beginning of line.
+    output += "### BEGIN MEMORY TOOL REPORT (error hash=#%016X#)\n" % \
+        self.ErrorHash()
+    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"
+      (stdoutbuf, stderrbuf) = filter.communicate(buf.encode('latin-1'))
+      demangled_names = stdoutbuf.split("\n")
+
+      i = 0
+      for frame in backtrace[1]:
+        output += ("  " + demangled_names[i])
+        i = i + 1
+
+        global TheAddressTable
+        if TheAddressTable != None and frame[SRC_FILE_DIR] == "":
+           # Try using gdb
+           foo = TheAddressTable.GetFileLine(frame[OBJECT_FILE],
+                                             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"
+
+    for additional in self._additional:
+      output += additional + "\n"
+
+    assert self._suppression != None, "Your Valgrind doesn't generate " \
+                                      "suppressions - is it too old?"
+
+    if self._testcase:
+      output += "The report came from the `%s` test.\n" % self._testcase
+    output += "Suppression (error hash=#%016X#):\n" % self.ErrorHash()
+    output += ("  For more info on using suppressions see "
+               "http://dev.chromium.org/developers/tree-sheriffs/sheriff-details-chromium/memory-sheriff#TOC-Suppressing-memory-reports")
+
+    # Widen suppression slightly to make portable between mac and linux
+    # TODO(timurrrr): Oops, these transformations should happen
+    # BEFORE calculating the hash!
+    supp = self._suppression;
+    supp = supp.replace("fun:_Znwj", "fun:_Znw*")
+    supp = supp.replace("fun:_Znwm", "fun:_Znw*")
+    supp = supp.replace("fun:_Znaj", "fun:_Zna*")
+    supp = supp.replace("fun:_Znam", "fun:_Zna*")
+
+    # Make suppressions even less platform-dependent.
+    for sz in [1, 2, 4, 8]:
+      supp = supp.replace("Memcheck:Addr%d" % sz, "Memcheck:Unaddressable")
+      supp = supp.replace("Memcheck:Value%d" % sz, "Memcheck:Uninitialized")
+    supp = supp.replace("Memcheck:Cond", "Memcheck:Uninitialized")
+
+    # Split into lines so we can enforce length limits
+    supplines = supp.split("\n")
+    supp = None  # to avoid re-use
+
+    # 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.)
+    newlen = min(26, len(supplines));
+
+    # Drop boring frames and all the following.
+    enough_frames = False
+    for frameno in range(newlen):
+      for boring_caller in _BORING_CALLERS:
+        if re.match("^ +fun:%s$" % boring_caller, supplines[frameno]):
+          newlen = frameno
+          enough_frames = True
+          break
+      if enough_frames:
+        break
+    if (len(supplines) > newlen):
+      supplines = supplines[0:newlen]
+      supplines.append("}")
+
+    for frame in range(len(supplines)):
+      # Replace the always-changing anonymous namespace prefix with "*".
+      m = re.match("( +fun:)_ZN.*_GLOBAL__N_.*\.cc_" +
+                   "[0-9a-fA-F]{8}_[0-9a-fA-F]{8}(.*)",
+                   supplines[frame])
+      if m:
+        supplines[frame] = "*".join(m.groups())
+
+    output += "\n".join(supplines) + "\n"
+    output += "### END MEMORY TOOL REPORT (error hash=#%016X#)\n" % \
+        self.ErrorHash()
+
+    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]
+
+        if frame[SRC_FILE_DIR] != "":
+          rep += frame[SRC_FILE_DIR] + "/" + frame[SRC_FILE_NAME]
+        else:
+          rep += frame[OBJECT_FILE]
+
+    return rep
+
+  # This is a device-independent hash identifying the suppression.
+  # By printing out this hash we can find duplicate reports between tests and
+  # different shards running on multiple buildbots
+  def ErrorHash(self):
+    return int(hashlib.md5(self.UniqueString()).hexdigest()[:16], 16)
+
+  def __hash__(self):
+    return hash(self.UniqueString())
+  def __eq__(self, rhs):
+    return self.UniqueString() == rhs
+
+def log_is_finished(f, force_finish):
+  f.seek(0)
+  prev_line = ""
+  while True:
+    line = f.readline()
+    if line == "":
+      if not force_finish:
+        return False
+      # Okay, the log is not finished but we can make it up to be parseable:
+      if prev_line.strip() in ["</error>", "</errorcounts>", "</status>"]:
+        f.write("</valgrindoutput>\n")
+        return True
+      return False
+    if '</valgrindoutput>' in line:
+      # Valgrind often has garbage after </valgrindoutput> upon crash.
+      f.truncate()
+      return True
+    prev_line = line
+
+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 = {
+      "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,
+      "Memcheck sanity test 07 (new/read right).": 1,
+      "Memcheck sanity test 08 (new/write left).": 1,
+      "Memcheck sanity test 09 (new/write right).": 1,
+      "Memcheck sanity test 10 (write after free).": 1,
+      "Memcheck sanity test 11 (write after delete).": 1,
+      "Memcheck sanity test 12 (array deleted without []).": 1,
+      "Memcheck sanity test 13 (single element deleted with []).": 1,
+      "Memcheck sanity test 14 (malloc/read uninit).": 1,
+      "Memcheck sanity test 15 (new/read uninit).": 1,
+  }
+
+  # 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, testcase, check_sanity=False):
+    '''Reads in a set of files and prints Memcheck report.
+
+    Args:
+      files: A list of filenames.
+      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 self._use_gdb:
+      TheAddressTable = gdb_helper.AddressTable()
+    else:
+      TheAddressTable = None
+    cur_report_errors = set()
+    suppcounts = defaultdict(int)
+    badfiles = set()
+
+    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
+      skip = False
+      origsize = os.path.getsize(file)
+      while (running and not found and not skip and
+             (firstrun or
+              ((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 len(ps_out.readlines()) < 2:
+            running = False
+        else:
+          skip = True
+          running = False
+        found = log_is_finished(f, False)
+        if not running and not found:
+          logging.warn("Valgrind process PID = %s is not running but its "
+                       "XML log has not been finished correctly.\n"
+                       "Make it up by adding some closing tags manually." % pid)
+          found = log_is_finished(f, not running)
+        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:
+          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()
+            if i != lineno:
+              logging.warn("  %s" % context_data)
+            else:
+              logging.warn("> %s" % context_data)
+          context_file.close()
+          continue
+        if TheAddressTable != None:
+          load_objs = parsed_file.getElementsByTagName("load_obj")
+          for load_obj in load_objs:
+            obj = getTextOf(load_obj, "obj")
+            ip = getTextOf(load_obj, "ip")
+            TheAddressTable.AddBinaryAt(obj, ip)
+
+        commandline = None
+        preamble = parsed_file.getElementsByTagName("preamble")[0];
+        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 (self._show_all_leaks or
+              getTextOf(raw_error, "kind") != "Leak_PossiblyLost"):
+            error = ValgrindError(self._source_dir,
+                                  raw_error, commandline, testcase)
+            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=#%016X#'" % \
+                                      error.ErrorHash())
+              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");
+            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)
+
+    if parse_failed:
+      logging.error("FAIL! Couldn't parse Valgrind output file")
+      return -2
+
+    common.PrintUsedSuppressionsList(suppcounts)
+
+    retcode = 0
+    if cur_report_errors:
+      logging.error("FAIL! There were %s errors: " % len(cur_report_errors))
+
+      if TheAddressTable != None:
+        TheAddressTable.ResolveAll()
+
+      for error in cur_report_errors:
+        logging.error(error)
+
+      retcode = -1
+
+    # Report tool's insanity even if there were errors.
+    if check_sanity:
+      remaining_sanity_supp = MemcheckAnalyzer.SANITY_TEST_SUPPRESSIONS
+      for (name, count) in suppcounts.iteritems():
+        # Workaround for http://crbug.com/334074
+        if (name in remaining_sanity_supp and
+            remaining_sanity_supp[name] <= count):
+          del remaining_sanity_supp[name]
+      if remaining_sanity_supp:
+        logging.error("FAIL! Sanity check failed!")
+        logging.info("The following test errors were not handled: ")
+        for (name, count) in remaining_sanity_supp.iteritems():
+          logging.info("  * %dx %s" % (count, name))
+        retcode = -3
+
+    if retcode != 0:
+      return retcode
+
+    logging.info("PASS! No errors found!")
+    return 0
+
+
+def _main():
+  '''For testing only. The MemcheckAnalyzer class should be imported instead.'''
+  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 = MemcheckAnalyzer(options.source_dir, use_gdb=True)
+  return analyzer.Report(filenames, None)
+
+
+if __name__ == "__main__":
+  sys.exit(_main())