Improve tracing on OSX and Windows

tools/isolate/trace_inputs.py

 #!/usr/bin/env python
 # coding=utf-8
 # Copyright (c) 2012 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.
 
 """Traces an executable and its child processes and extract the files accessed
 by them.
 
 The implementation uses OS-specific API. The native Kernel logger and the ETL
@@ skipping 365 matching lines @@
       RE_SIGNAL = re.compile(r'^--- SIG[A-Z]+ .+ ---')
       # A process didn't handle a signal.
       RE_KILLED = re.compile(r'^\+\+\+ killed by ([A-Z]+) \+\+\+$')
       # A call was canceled.
       RE_UNAVAILABLE = re.compile(r'\)\s+= \? <unavailable>$')
       # Happens when strace fails to even get the function name.
       UNNAMED_FUNCTION = '????'
 
       # Arguments parsing.
       RE_CHDIR = re.compile(r'^\"(.+?)\"$')
-      RE_EXECVE = re.compile(r'^\"(.+?)\", \[.+?\], \[.+?\]$')
+      RE_EXECVE = re.compile(r'^\"(.+?)\", \[(.+)\], \[\/\* \d\d vars \*\/\]$')
       RE_OPEN2 = re.compile(r'^\"(.*?)\", ([A-Z\_\|]+)$')
       RE_OPEN3 = re.compile(r'^\"(.*?)\", ([A-Z\_\|]+), (\d+)$')
       RE_RENAME = re.compile(r'^\"(.+?)\", \"(.+?)\"$')
 
       class RelativePath(object):
         """A late-bound relative path."""
         def __init__(self, parent, value):
           self.parent = parent
           self.value = value
 
@@ skipping 99 matching lines @@
         """Transfers cwd."""
         if result == '? ERESTARTNOINTR (To be restarted)':
           return
         # Update the other process right away.
         childpid = int(result)
         child = self.root().get_or_set_proc(childpid)
         # Copy the cwd object.
         child.initial_cwd = self.get_cwd()
         assert child.parentid is None
         child.parentid = self.pid
+        # It is necessary because the logs are processed out of order.
+        assert childpid not in self.children
         self.children.append(childpid)
 
       def handle_close(self, _function, _args, _result):
         pass
 
       def handle_execve(self, _function, args, result):
-        self._handle_file(self.RE_EXECVE.match(args).group(1), result)
+        if result != '0':
+          return
+        m = self.RE_EXECVE.match(args)
+        self._handle_file(m.group(1), result)
 
       def handle_exit_group(self, _function, _args, _result):
         """Removes cwd."""
         self.cwd = None
 
       @staticmethod
       def handle_fork(_function, args, result):
         assert False, (args, result)
 
       def handle_open(self, _function, args, result):
@@ skipping 235 matching lines @@
         syscall::truncate:return,
         syscall::unlink:return,
         syscall::utimes:return,
       */
       """
 
   @classmethod
   def code(cls, pid, cwd):
     """Setups the D code to implement child process tracking.
 
-    Injects a fake chdir() trace to simplify parsing. The reason is that the
-    child process is already running at that point so:
+    Injects the pid and the initial cwd into the trace header for context.
+    The reason is that the child process is already running at that point so:
     - no proc_start() is logged for it.
     - there is no way to figure out the absolute path of cwd in kernel on OSX
 
     Since the child process is already started, initialize current_processes to
     1.
     """
     pid = str(pid)
     cwd = os.path.realpath(cwd).replace('\\', '\\\\').replace('%', '%%')
     return (
         'dtrace:::BEGIN {\n'
         '  current_processes = 1;\n'
         '  logindex = 0;\n'
-        '  trackedpid[') + pid + ('] = 1;\n'
-        '  printf("%d %d:%d chdir(\\"' + cwd + '\\") = 0\\n",\n'
-        '      logindex, 1, ' + pid + ');\n'
-        '  logindex++;\n'
-        '  printf("%d %d:%d %s_%s() = 0\\n",\n'
-        '      logindex, ppid, pid, probeprov, probename);\n'
+        '  trackedpid[' + pid + '] = 1;\n'
+        '  printf("%d %d:%d %s_%s(\\"' + cwd + '\\") = 0\\n",\n'
+        '      logindex, ppid, ' + pid + ', probeprov, probename);\n'
         '  logindex++;\n'
         '}\n') + cls.D_CODE
 
   class Context(ApiBase.Context):
     # This is the most common format. index pid function(args) = result
     RE_HEADER = re.compile(r'^\d+ (\d+):(\d+) ([a-zA-Z_\-]+)\((.*?)\) = (.+)$')
 
     # Arguments parsing.
+    RE_DTRACE_BEGIN = re.compile(r'^\"(.+?)\"$')
     RE_CHDIR = re.compile(r'^\"(.+?)\"$')
     RE_OPEN = re.compile(r'^\"(.+?)\", (\d+), (-?\d+)$')
     RE_RENAME = re.compile(r'^\"(.+?)\", \"(.+?)\"$')
 
     O_DIRECTORY = 0x100000
 
     class Process(ApiBase.Context.Process):
       pass
 
+    def __init__(self, blacklist):
+      super(Dtrace.Context, self).__init__(blacklist)
+      # Process ID of the trace_child_process.py wrapper script instance.
+      self._tracer_pid = None
+      # First process to be started by self._tracer_pid.
+      self._initial_pid = None
+      self._initial_cwd = None
+
     def on_line(self, line):
       match = self.RE_HEADER.match(line)
       assert match, line
       fn = getattr(
           self,
           'handle_%s' % match.group(3).replace('-', '_'),
           self._handle_ignored)
       return fn(
           int(match.group(1)),
           int(match.group(2)),
           match.group(3),
           match.group(4),
           match.group(5))
 
-    def handle_dtrace_BEGIN(self, _ppid, _pid, _function, args, _result):
-      pass
+    def handle_dtrace_BEGIN(self, _ppid, pid, _function, args, _result):
+      assert not self._tracer_pid and not self._initial_pid
+      self._tracer_pid = pid
+      self._initial_cwd = self.RE_DTRACE_BEGIN.match(args).group(1)
 
     def handle_proc_start(self, ppid, pid, _function, _args, result):
-      """Transfers cwd."""
+      """Transfers cwd.
+
+      The dtrace script already takes care of only tracing the processes that
+      are child of the traced processes so there is no need to verify the
+      process hierarchy.
+      """
       assert result == '0'
-      cwd = self.processes[ppid].cwd
       assert pid not in self.processes
+      assert (ppid == self._tracer_pid) != bool(self._initial_pid)
+      if not self._initial_pid:
+        self._initial_pid = pid
+        ppid = None
+        cwd = self._initial_cwd
+      else:
+        parent = self.processes[ppid]
+        cwd = parent.cwd
       proc = self.processes[pid] = self.Process(self, pid, cwd, ppid)
       proc.cwd = cwd
+      logging.debug('New child: %s -> %d' % (ppid, pid))
 
     def handle_proc_exit(self, _ppid, pid, _function, _args, _result):
       """Removes cwd."""
-      self.processes[pid].cwd = None
+      if pid != self._tracer_pid:
+        # self._tracer_pid is not traced itself.
+        self.processes[pid].cwd = None
 
-    def handle_chdir(self, ppid, pid, _function, args, result):
+    def handle_chdir(self, _ppid, pid, _function, args, result):
       """Updates cwd."""
+      assert self._tracer_pid
+      assert pid in self.processes
       if result.startswith('0'):
         cwd = self.RE_CHDIR.match(args).group(1)
         if not cwd.startswith('/'):
           cwd2 = os.path.join(self.processes[pid].cwd, cwd)
           logging.debug('handle_chdir(%d, %s) -> %s' % (pid, cwd, cwd2))
         else:
           logging.debug('handle_chdir(%d, %s)' % (pid, cwd))
           cwd2 = cwd
-        proc = self.processes.setdefault(
-            pid, self.Process(self, pid, cwd2, ppid))
-        proc.cwd = cwd2
+        self.processes[pid].cwd = cwd2
       else:
         assert False, 'Unexecpected fail: %s' % result
 
     def handle_open_nocancel(self, ppid, pid, function, args, result):
       return self.handle_open(ppid, pid, function, args, result)
 
     def handle_open(self, _ppid, pid, function, args, result):
       match = self.RE_OPEN.match(args)
       assert match, (pid, function, args, result)
       args = match.groups()
@@ skipping 132 matching lines @@
     with open(logname, 'rb') as logfile:
       lines = [f for f in logfile.readlines() if f.strip()]
     lines = sorted(lines, key=lambda l: int(l.split(' ', 1)[0]))
     with open(logname, 'wb') as logfile:
       logfile.write(''.join(lines))
 
 
 class LogmanTrace(ApiBase):
   """Uses the native Windows ETW based tracing functionality to trace a child
   process.
+
+  Caveat: this implementations doesn't track cwd or initial_cwd.
   """
   class Context(ApiBase.Context):
     """Processes a ETW log line and keeps the list of existent and non
     existent files accessed.
 
     Ignores directories.
     """
     # Only the useful headers common to all entries are listed there. Any column
     # at 19 or higher is dependent on the specific event.
     EVENT_NAME = 0
     TYPE = 1
     PID = 9
     TID = 10
     PROCESSOR_ID = 11
     TIMESTAMP = 16
 
     class Process(ApiBase.Context.Process):
-      pass
+      def __init__(self, *args):
+        super(LogmanTrace.Context.Process, self).__init__(*args)
+        # Handle file objects that succeeded.
+        self.file_objects = {}
 
     def __init__(self, blacklist):
       super(LogmanTrace.Context, self).__init__(blacklist)
       self._drive_map = DosDriveMap()
-      self._first_line = False
       # Threads mapping to the corresponding process id.
       self._threads_active = {}
+      # Process ID of the tracer, e.g. tracer_inputs.py
+      self._tracer_pid = None
+      # First process to be started by self._tracer_pid.
+      self._initial_pid = None
+      self._line_number = 0
 
     def on_csv_line(self, line):
       """Processes a CSV Event line."""
       # So much white space!
       line = [i.strip() for i in line]
-      if not self._first_line:
+      self._line_number += 1
+      if self._line_number == 1:
         assert line == [
           u'Event Name',
           u'Type',
           u'Event ID',
           u'Version',
           u'Channel',
           u'Level',  # 5
           u'Opcode',
           u'Task',
           u'Keyword',
           u'PID',
           u'TID',  # 10
           u'Processor Number',
           u'Instance ID',
           u'Parent Instance ID',
           u'Activity ID',
           u'Related Activity ID',  # 15
           u'Clock-Time',
           u'Kernel(ms)',  # Both have a resolution of ~15ms which makes them
           u'User(ms)',    # pretty much useless.
           u'User Data',
         ]
-        self._first_line = True
         return
 
       # As you can see, the CSV is full of useful non-redundant information:
       # Event ID
       assert line[2] == '0'
       # Version
       assert line[3] in ('2', '3'), line[3]
       # Channel
       assert line[4] == '0'
       # Level
@@ skipping 24 matching lines @@
           'handle_%s_%s' % (line[self.EVENT_NAME], line[self.TYPE]),
           None)
       if not handler:
         # Try to get an universal fallback
         handler = getattr(self, 'handle_%s_Any' % line[self.EVENT_NAME], None)
       if handler:
         handler(line)
       else:
         assert False, '%s_%s' % (line[self.EVENT_NAME], line[self.TYPE])
 
+    def _thread_to_process(self, tid):
+      """Finds the process from the thread id."""
+      tid = int(tid, 16)
+      return self.processes.get(self._threads_active.get(tid))
+
     @staticmethod
     def handle_EventTrace_Header(line):
       """Verifies no event was dropped, e.g. no buffer overrun occured."""
       #BUFFER_SIZE = 19
       #VERSION = 20
       #PROVIDER_VERSION = 21
       #NUMBER_OF_PROCESSORS = 22
       #END_TIME = 23
       #TIMER_RESOLUTION = 24
       #MAX_FILE_SIZE = 25
@@ skipping 10 matching lines @@
       #START_TIME = 36
       #RESERVED_FLAGS = 37
       #BUFFERS_LOST = 38
       #SESSION_NAME_STRING = 39
       #LOG_FILE_NAME_STRING = 40
       assert line[EVENTS_LOST] == '0'
 
     def handle_EventTrace_Any(self, line):
       pass
 
+    def handle_FileIo_Cleanup(self, line):
+      """General wisdom: if a file is closed, it's because it was opened.

[MAD, 2012/05/30 15:39:00]

:-)

[M-A Ruel, 2012/05/30 15:57:16]

Note that it is a reference to line 1197, which doesn't return the result code.
:(

+
+      Note that FileIo_Close is not used since if a file was opened properly but
+      not closed before the process exits, only Cleanup will be logged.
+      """
+      #IRP = 19
+      TTID = 20  # Thread ID, that's what we want.
+      FILE_OBJECT = 21
+      #FILE_KEY = 22
+      proc = self._thread_to_process(line[TTID])
+      if not proc:
+        # Not a process we care about.
+        return
+      file_object = line[FILE_OBJECT]
+      if file_object in proc.file_objects:
+        proc.add_file(proc.file_objects.pop(file_object))
+
     def handle_FileIo_Create(self, line):
       """Handles a file open.
 
       All FileIo events are described at
       http://msdn.microsoft.com/library/windows/desktop/aa363884.aspx
       for some value of 'description'.
 
       " (..) process and thread id values of the IO events (..) are not valid "
       http://msdn.microsoft.com/magazine/ee358703.aspx
+
+      The FileIo.Create event doesn't return if the CreateFile() call
+      succeeded so keep track of the file_object and look if it is closed.

[MAD, 2012/05/30 15:39:00]

add a coma "," after succeeded please...

"look if it is" -> "check that is is"

[M-A Ruel, 2012/05/30 15:57:16]

Changed the wording a little.

       """
       #IRP = 19
       TTID = 20  # Thread ID, that's what we want.
-      #FILE_OBJECT = 21
+      FILE_OBJECT = 21
       #CREATE_OPTIONS = 22
       #FILE_ATTRIBUTES = 23
       #SHARE_ACCESS = 24
       OPEN_PATH = 25
 
-      # Find the process from the thread id.
-      tid = int(line[TTID], 16)
-      proc = self.processes.get(self._threads_active.get(tid))
+      proc = self._thread_to_process(line[TTID])
       if not proc:
         # Not a process we care about.
         return
 
       match = re.match(r'^\"(.+)\"$', line[OPEN_PATH])
       raw_path = match.group(1)
       # Ignore directories and bare drive right away.
       if raw_path.endswith(os.path.sep):
         return
       filename = self._drive_map.to_dos(raw_path)
-      # Ignore bare drive right away.
-      if len(raw_path) == 2:
+      # Ignore bare drive right away. Some may still fall through with format
+      # like '\\?\X:'
+      if len(filename) == 2:
         return
-      proc.add_file(filename)
+      file_object = line[FILE_OBJECT]
+      # Override any stale file object
+      proc.file_objects[file_object] = filename
 
     def handle_FileIo_Rename(self, line):
       # TODO(maruel): Handle?
       pass
 
     def handle_FileIo_Any(self, line):
       pass
 
     def handle_Process_Any(self, line):
       pass
@@ skipping 11 matching lines @@
       #EXIT_STATUS = 23
       #DIRECTORY_TABLE_BASE = 24
       #USER_SID = 25
       IMAGE_FILE_NAME = 26
       #COMMAND_LINE = 27
 
       ppid = int(line[PARENT_PID], 16)
       if line[IMAGE_FILE_NAME] == '"logman.exe"':
         # logman's parent is trace_input.py or whatever tool using it as a
         # library. Trace any other children started by it.
-        assert ppid not in self.processes
-        self.processes[ppid] = self.Process(self, ppid, None, None)
+        assert not self._tracer_pid
+        self._tracer_pid = ppid
         logging.info('Found logman\'s parent at %d' % ppid)
 
     def handle_Process_End(self, line):
       # Look if it is logman terminating, if so, grab the parent's process pid
       # and inject cwd.
       pid = line[self.PID]
       if pid in self.processes:
         logging.info('Terminated: %d' % pid)
+        self.processes[pid].cwd = None
 
     def handle_Process_Start(self, line):
       """Handles a new child process started by PID."""
       #UNIQUE_PROCESS_KEY = 19
       PROCESS_ID = 20
       #PARENT_PID = 21
       #SESSION_ID = 22
       #EXIT_STATUS = 23
       #DIRECTORY_TABLE_BASE = 24
       #USER_SID = 25
       IMAGE_FILE_NAME = 26
       #COMMAND_LINE = 27
 
       ppid = line[self.PID]
       pid = int(line[PROCESS_ID], 16)
-      if ppid in self.processes:
+      if ppid == self._tracer_pid:
         # Need to ignore processes we don't know about because the log is
         # system-wide.
         if line[IMAGE_FILE_NAME] == '"logman.exe"':
           # Skip the shutdown call when "logman.exe stop" is executed.
           return
+        self._initial_pid = self._initial_pid or pid
+        assert pid not in self.processes
+        self.processes[pid] = self.Process(self, pid, None, None)
+        logging.info(
+            'New child: %d -> %d %s' % (ppid, pid, line[IMAGE_FILE_NAME]))
+      elif ppid in self.processes:
+        # Grand-children
         assert pid not in self.processes
         self.processes[pid] = self.Process(self, pid, None, ppid)
         logging.info(
             'New child: %d -> %d %s' % (ppid, pid, line[IMAGE_FILE_NAME]))
 
     def handle_Thread_End(self, line):
       """Has the same parameters as Thread_Start."""
       tid = int(line[self.TID], 16)
       self._threads_active.pop(tid, None)
 
@@ skipping 47 matching lines @@
       'TMP',
     )
     for i in vars_to_ignore:
       if os.environ.get(i):
         self.IGNORED.add(os.environ[i])
 
     # Also add their short path name equivalents.
     for i in list(self.IGNORED):
       self.IGNORED.add(GetShortPathName(i.replace('/', os.path.sep)))
 
-    # Add this one last since it has no short path name equivalent.
+    # Add these last since they have no short path name equivalent.
     self.IGNORED.add('\\SystemRoot')
+    # All the NTFS metadata is in the form x:\$EXTEND or stuff like that.
+    for letter in (chr(l) for l in xrange(ord('C'), ord('Z')+1)):
+      self.IGNORED.add('%s\\\$' % letter)
+      # TODO(maruel): Remove the need to add these.
+      self.IGNORED.add('\\\\?\\%s\\$' % letter)
     self.IGNORED = tuple(sorted(self.IGNORED))
 
   @staticmethod
   def clean_trace(logname):
     if os.path.isfile(logname):
       os.remove(logname)
     if os.path.isfile(logname + '.etl'):
       os.remove(logname + '.etl')
 
   @classmethod
@@ skipping 498 matching lines @@
       os.path.abspath(options.log),
       args,
       options.root_dir,
       options.cwd,
       options.product_dir,
       options.force)
 
 
 if __name__ == '__main__':
   sys.exit(main())