13 files changed, 244 insertions, 110 deletions

diff --git a/git_command.py b/git_command.py
index 19100fa9..56e18e02 100644
--- a/git_command.py
+++ b/git_command.py
@@ -230,12 +230,11 @@ class GitCommand(object):
     stderr = (subprocess.STDOUT if merge_output else
               (subprocess.PIPE if capture_stderr else None))
 
+    dbg = ''
     if IsTrace():
       global LAST_CWD
       global LAST_GITDIR
 
-      dbg = ''
-
       if cwd and LAST_CWD != cwd:
         if LAST_GITDIR or LAST_CWD:
           dbg += '\n'
@@ -263,31 +262,31 @@ class GitCommand(object):
         dbg += ' 2>|'
       elif stderr == subprocess.STDOUT:
         dbg += ' 2>&1'
-      Trace('%s', dbg)
-
-    try:
-      p = subprocess.Popen(command,
-                           cwd=cwd,
-                           env=env,
-                           encoding='utf-8',
-                           errors='backslashreplace',
-                           stdin=stdin,
-                           stdout=stdout,
-                           stderr=stderr)
-    except Exception as e:
-      raise GitError('%s: %s' % (command[1], e))
-
-    if ssh_proxy:
-      ssh_proxy.add_client(p)
 
-    self.process = p
+    with Trace('git command %s %s with debug: %s', LAST_GITDIR, command, dbg):
+      try:
+        p = subprocess.Popen(command,
+                            cwd=cwd,
+                            env=env,
+                            encoding='utf-8',
+                            errors='backslashreplace',
+                            stdin=stdin,
+                            stdout=stdout,
+                            stderr=stderr)
+      except Exception as e:
+        raise GitError('%s: %s' % (command[1], e))
 
-    try:
-      self.stdout, self.stderr = p.communicate(input=input)
-    finally:
       if ssh_proxy:
-        ssh_proxy.remove_client(p)
-    self.rc = p.wait()
+        ssh_proxy.add_client(p)
+
+      self.process = p
+
+      try:
+        self.stdout, self.stderr = p.communicate(input=input)
+      finally:
+        if ssh_proxy:
+          ssh_proxy.remove_client(p)
+      self.rc = p.wait()
 
   @staticmethod
   def _GetBasicEnv():
diff --git a/git_config.py b/git_config.py
index 6f80ae08..98cade32 100644
--- a/git_config.py
+++ b/git_config.py
@@ -349,9 +349,9 @@ class GitConfig(object):
     except OSError:
       return None
     try:
-      Trace(': parsing %s', self.file)
-      with open(self._json) as fd:
-        return json.load(fd)
+      with Trace(': parsing %s', self.file):
+        with open(self._json) as fd:
+          return json.load(fd)
     except (IOError, ValueError):
       platform_utils.remove(self._json, missing_ok=True)
       return None
diff --git a/git_refs.py b/git_refs.py
index 2d4a8090..300d2b30 100644
--- a/git_refs.py
+++ b/git_refs.py
@@ -67,38 +67,37 @@ class GitRefs(object):
       self._LoadAll()
 
   def _NeedUpdate(self):
-    Trace(': scan refs %s', self._gitdir)
-
-    for name, mtime in self._mtime.items():
-      try:
-        if mtime != os.path.getmtime(os.path.join(self._gitdir, name)):
+    with Trace(': scan refs %s', self._gitdir):
+      for name, mtime in self._mtime.items():
+        try:
+          if mtime != os.path.getmtime(os.path.join(self._gitdir, name)):
+            return True
+        except OSError:
           return True
-      except OSError:
-        return True
-    return False
+      return False
 
   def _LoadAll(self):
-    Trace(': load refs %s', self._gitdir)
-
-    self._phyref = {}
-    self._symref = {}
-    self._mtime = {}
-
-    self._ReadPackedRefs()
-    self._ReadLoose('refs/')
-    self._ReadLoose1(os.path.join(self._gitdir, HEAD), HEAD)
-
-    scan = self._symref
-    attempts = 0
-    while scan and attempts < 5:
-      scan_next = {}
-      for name, dest in scan.items():
-        if dest in self._phyref:
-          self._phyref[name] = self._phyref[dest]
-        else:
-          scan_next[name] = dest
-      scan = scan_next
-      attempts += 1
+    with Trace(': load refs %s', self._gitdir):
+
+      self._phyref = {}
+      self._symref = {}
+      self._mtime = {}
+
+      self._ReadPackedRefs()
+      self._ReadLoose('refs/')
+      self._ReadLoose1(os.path.join(self._gitdir, HEAD), HEAD)
+
+      scan = self._symref
+      attempts = 0
+      while scan and attempts < 5:
+        scan_next = {}
+        for name, dest in scan.items():
+          if dest in self._phyref:
+            self._phyref[name] = self._phyref[dest]
+          else:
+            scan_next[name] = dest
+        scan = scan_next
+        attempts += 1
 
   def _ReadPackedRefs(self):
     path = os.path.join(self._gitdir, 'packed-refs')
diff --git a/main.py b/main.py
index c54f9281..e629b30f 100755
--- a/main.py
+++ b/main.py
@@ -37,7 +37,7 @@ except ImportError:
 
 from color import SetDefaultColoring
 import event_log
-from repo_trace import SetTrace
+from repo_trace import SetTrace, Trace, SetTraceToStderr
 from git_command import user_agent
 from git_config import RepoConfig
 from git_trace2_event_log import EventLog
@@ -109,6 +109,9 @@ global_options.add_option('--color',
 global_options.add_option('--trace',
                           dest='trace', action='store_true',
                           help='trace git command execution (REPO_TRACE=1)')
+global_options.add_option('--trace_to_stderr',
+                          dest='trace_to_stderr', action='store_true',
+                          help='trace outputs go to stderr in addition to .repo/TRACE_FILE')
 global_options.add_option('--trace-python',
                           dest='trace_python', action='store_true',
                           help='trace python command execution')
@@ -198,9 +201,6 @@ class _Repo(object):
     """Execute the requested subcommand."""
     result = 0
 
-    if gopts.trace:
-      SetTrace()
-
     # Handle options that terminate quickly first.
     if gopts.help or gopts.help_all:
       self._PrintHelp(short=False, all_commands=gopts.help_all)
@@ -652,17 +652,26 @@ def _Main(argv):
   Version.wrapper_path = opt.wrapper_path
 
   repo = _Repo(opt.repodir)
+
   try:
     init_http()
     name, gopts, argv = repo._ParseArgs(argv)
-    run = lambda: repo._Run(name, gopts, argv) or 0
-    if gopts.trace_python:
-      import trace
-      tracer = trace.Trace(count=False, trace=True, timing=True,
-                           ignoredirs=set(sys.path[1:]))
-      result = tracer.runfunc(run)
-    else:
-      result = run()
+
+    if gopts.trace:
+      SetTrace()
+
+    if gopts.trace_to_stderr:
+      SetTraceToStderr()
+
+    with Trace('starting new command: %s', ', '.join([name] + argv), first_trace=True):
+      run = lambda: repo._Run(name, gopts, argv) or 0
+      if gopts.trace_python:
+        import trace
+        tracer = trace.Trace(count=False, trace=True, timing=True,
+                             ignoredirs=set(sys.path[1:]))
+        result = tracer.runfunc(run)
+      else:
+        result = run()
   except KeyboardInterrupt:
     print('aborted by user', file=sys.stderr)
     result = 1
diff --git a/project.py b/project.py
index 1c85b044..b975b72a 100644
--- a/project.py
+++ b/project.py
@@ -41,7 +41,7 @@ from error import ManifestInvalidRevisionError, ManifestInvalidPathError
 from error import NoManifestException, ManifestParseError
 import platform_utils
 import progress
-from repo_trace import IsTrace, Trace
+from repo_trace import Trace
 
 from git_refs import GitRefs, HEAD, R_HEADS, R_TAGS, R_PUB, R_M, R_WORKTREE_M
 
@@ -2416,16 +2416,16 @@ class Project(object):
         srcUrl = 'http' + srcUrl[len('persistent-http'):]
       cmd += [srcUrl]
 
-      if IsTrace():
-        Trace('%s', ' '.join(cmd))
-      if verbose:
-        print('%s: Downloading bundle: %s' % (self.name, srcUrl))
-      stdout = None if verbose else subprocess.PIPE
-      stderr = None if verbose else subprocess.STDOUT
-      try:
-        proc = subprocess.Popen(cmd, stdout=stdout, stderr=stderr)
-      except OSError:
-        return False
+      proc = None
+      with Trace('Fetching bundle: %s', ' '.join(cmd)):
+        if verbose:
+          print('%s: Downloading bundle: %s' % (self.name, srcUrl))
+        stdout = None if verbose else subprocess.PIPE
+        stderr = None if verbose else subprocess.STDOUT
+        try:
+          proc = subprocess.Popen(cmd, stdout=stdout, stderr=stderr)
+        except OSError:
+          return False
 
       (output, _) = proc.communicate()
       curlret = proc.returncode
diff --git a/repo_trace.py b/repo_trace.py
index 7be0c045..0ff3b694 100644
--- a/repo_trace.py
+++ b/repo_trace.py
@@ -15,26 +15,128 @@
 """Logic for tracing repo interactions.
 
 Activated via `repo --trace ...` or `REPO_TRACE=1 repo ...`.
+
+Temporary: Tracing is always on. Set `REPO_TRACE=0` to turn off.
+To also include trace outputs in stderr do `repo --trace_to_stderr ...`
 """
 
 import sys
 import os
+import tempfile
+import time
+from contextlib import ContextDecorator
 
 # Env var to implicitly turn on tracing.
 REPO_TRACE = 'REPO_TRACE'
 
-_TRACE = os.environ.get(REPO_TRACE) == '1'
+# Temporarily set tracing to always on unless user expicitly sets to 0.
+_TRACE = os.environ.get(REPO_TRACE) != '0'
+
+_TRACE_TO_STDERR = False
+
+_TRACE_FILE = None
+
+_TRACE_FILE_NAME = 'TRACE_FILE'
+
+_MAX_SIZE = 5  # in mb
+
+_NEW_COMMAND_SEP = '+++++++++++++++NEW COMMAND+++++++++++++++++++'
+
+
+def IsStraceToStderr():
+  return _TRACE_TO_STDERR
 
 
 def IsTrace():
   return _TRACE
 
 
+def SetTraceToStderr():
+  global _TRACE_TO_STDERR
+  _TRACE_TO_STDERR = True
+
+
 def SetTrace():
   global _TRACE
   _TRACE = True
 
 
-def Trace(fmt, *args):
-  if IsTrace():
-    print(fmt % args, file=sys.stderr)
+def _SetTraceFile():
+  global _TRACE_FILE
+  _TRACE_FILE = _GetTraceFile()
+
+
+class Trace(ContextDecorator):
+
+    def _time(self):
+      """Generate nanoseconds of time in a py3.6 safe way"""
+      return int(time.time()*1e+9)
+
+    def __init__(self, fmt, *args, first_trace=False):
+      if not IsTrace():
+        return
+      self._trace_msg = fmt % args
+
+      if not _TRACE_FILE:
+        _SetTraceFile()
+
+      if first_trace:
+        _ClearOldTraces()
+        self._trace_msg = '%s %s' % (_NEW_COMMAND_SEP, self._trace_msg)
+
+
+    def __enter__(self):
+      if not IsTrace():
+        return self
+
+      print_msg = f"PID: {os.getpid()} START: {self._time()} :" + self._trace_msg + '\n'
+
+      with open(_TRACE_FILE, 'a') as f:
+        print(print_msg, file=f)
+
+      if _TRACE_TO_STDERR:
+        print(print_msg, file=sys.stderr)
+
+      return self
+
+    def __exit__(self, *exc):
+      if not IsTrace():
+        return False
+
+      print_msg = f"PID: {os.getpid()} END: {self._time()} :" + self._trace_msg + '\n'
+
+      with open(_TRACE_FILE, 'a') as f:
+        print(print_msg, file=f)
+
+      if _TRACE_TO_STDERR:
+        print(print_msg, file=sys.stderr)
+
+      return False
+
+
+def _GetTraceFile():
+  """Get the trace file or create one."""
+  # TODO: refactor to pass repodir to Trace.
+  repo_dir = os.path.dirname(os.path.dirname(__file__))
+  trace_file = os.path.join(repo_dir, _TRACE_FILE_NAME)
+  print('Trace outputs in %s' % trace_file)
+  return trace_file
+
+def _ClearOldTraces():
+  """Clear traces from old commands if trace file is too big.
+
+  Note: If the trace file contains output from two `repo`
+        commands that were running at the same time, this
+        will not work precisely.
+  """
+  if os.path.isfile(_TRACE_FILE):
+    while os.path.getsize(_TRACE_FILE)/(1024*1024) > _MAX_SIZE:
+      temp = tempfile.NamedTemporaryFile(mode='w', delete=False)
+      with open(_TRACE_FILE, 'r', errors='ignore') as fin:
+        trace_lines = fin.readlines()
+        for i , l in enumerate(trace_lines):
+          if 'END:' in l and _NEW_COMMAND_SEP in l:
+            temp.writelines(trace_lines[i+1:])
+            break
+      temp.close()
+      os.replace(temp.name, _TRACE_FILE)
diff --git a/run_tests b/run_tests
index 573dd446..7c9ff41d 100755
--- a/run_tests
+++ b/run_tests
@@ -20,6 +20,7 @@ import os
 import shutil
 import subprocess
 import sys
+import repo_trace
 
 
 def find_pytest():
diff --git a/ssh.py b/ssh.py
index 450383dc..004fdbad 100644
--- a/ssh.py
+++ b/ssh.py
@@ -182,28 +182,29 @@ class ProxyManager:
     # be important because we can't tell that that 'git@myhost.com' is the same
     # as 'myhost.com' where "User git" is setup in the user's ~/.ssh/config file.
     check_command = command_base + ['-O', 'check']
-    try:
-      Trace(': %s', ' '.join(check_command))
-      check_process = subprocess.Popen(check_command,
-                                       stdout=subprocess.PIPE,
-                                       stderr=subprocess.PIPE)
-      check_process.communicate()  # read output, but ignore it...
-      isnt_running = check_process.wait()
-
-      if not isnt_running:
-        # Our double-check found that the master _was_ infact running.  Add to
-        # the list of keys.
-        self._master_keys[key] = True
-        return True
-    except Exception:
-      # Ignore excpetions.  We we will fall back to the normal command and print
-      # to the log there.
-      pass
+    with Trace('Call to ssh (check call): %s', ' '.join(check_command)):
+      try:
+        check_process = subprocess.Popen(check_command,
+                                        stdout=subprocess.PIPE,
+                                        stderr=subprocess.PIPE)
+        check_process.communicate()  # read output, but ignore it...
+        isnt_running = check_process.wait()
+
+        if not isnt_running:
+          # Our double-check found that the master _was_ infact running.  Add to
+          # the list of keys.
+          self._master_keys[key] = True
+          return True
+      except Exception:
+        # Ignore excpetions.  We we will fall back to the normal command and
+        # print to the log there.
+        pass
 
     command = command_base[:1] + ['-M', '-N'] + command_base[1:]
+    p = None
     try:
-      Trace(': %s', ' '.join(command))
-      p = subprocess.Popen(command)
+      with Trace('Call to ssh: %s', ' '.join(command)):
+        p = subprocess.Popen(command)
     except Exception as e:
       self._master_broken.value = True
       print('\nwarn: cannot enable ssh control master for %s:%s\n%s'
diff --git a/subcmds/sync.py b/subcmds/sync.py
index fe63b484..082b254f 100644
--- a/subcmds/sync.py
+++ b/subcmds/sync.py
@@ -60,7 +60,7 @@ from error import RepoChangedException, GitError, ManifestParseError
 import platform_utils
 from project import SyncBuffer
 from progress import Progress
-from repo_trace import IsTrace, Trace
+from repo_trace import Trace
 import ssh
 from wrapper import Wrapper
 from manifest_xml import GitcManifest
@@ -739,7 +739,6 @@ later is required to fix a server side protocol bug.
     bak_dir = os.path.join(objdir, '.repo', 'pack.bak')
     if not _BACKUP_OBJECTS or not platform_utils.isdir(pack_dir):
       return
-    saved = []
     files = set(platform_utils.listdir(pack_dir))
     to_backup = []
     for f in files:
@@ -751,12 +750,10 @@ later is required to fix a server side protocol bug.
     for fname in to_backup:
       bak_fname = os.path.join(bak_dir, fname)
       if not os.path.exists(bak_fname):
-        saved.append(fname)
-        # Use a tmp file so that we are sure of a complete copy.
-        shutil.copy(os.path.join(pack_dir, fname), bak_fname + '.tmp')
-        shutil.move(bak_fname + '.tmp', bak_fname)
-    if saved:
-      Trace('%s saved %s', bare_git._project.name, ' '.join(saved))
+        with Trace('%s saved %s', bare_git._project.name, fname):
+          # Use a tmp file so that we are sure of a complete copy.
+          shutil.copy(os.path.join(pack_dir, fname), bak_fname + '.tmp')
+          shutil.move(bak_fname + '.tmp', bak_fname)
 
   def _GCProjects(self, projects, opt, err_event):
     pm = Progress('Garbage collecting', len(projects), delay=False, quiet=opt.quiet)
diff --git a/tests/test_git_config.py b/tests/test_git_config.py
index a4fad9ef..0df38430 100644
--- a/tests/test_git_config.py
+++ b/tests/test_git_config.py
@@ -19,6 +19,7 @@ import tempfile
 import unittest
 
 import git_config
+import repo_trace
 
 
 def fixture(*paths):
@@ -33,9 +34,16 @@ class GitConfigReadOnlyTests(unittest.TestCase):
   def setUp(self):
     """Create a GitConfig object using the test.gitconfig fixture.
     """
+
+    self.tempdirobj = tempfile.TemporaryDirectory(prefix='repo_tests')
+    repo_trace._TRACE_FILE = os.path.join(self.tempdirobj.name, 'TRACE_FILE_from_test')
+
     config_fixture = fixture('test.gitconfig')
     self.config = git_config.GitConfig(config_fixture)
 
+  def tearDown(self):
+    self.tempdirobj.cleanup()
+
   def test_GetString_with_empty_config_values(self):
     """
     Test config entries with no value.
@@ -109,9 +117,15 @@ class GitConfigReadWriteTests(unittest.TestCase):
   """Read/write tests of the GitConfig class."""
 
   def setUp(self):
+    self.tempdirobj = tempfile.TemporaryDirectory(prefix='repo_tests')
+    repo_trace._TRACE_FILE = os.path.join(self.tempdirobj.name, 'TRACE_FILE_from_test')
+
     self.tmpfile = tempfile.NamedTemporaryFile()
     self.config = self.get_config()
 
+  def tearDown(self):
+    self.tempdirobj.cleanup()
+
   def get_config(self):
     """Get a new GitConfig instance."""
     return git_config.GitConfig(self.tmpfile.name)
diff --git a/tests/test_git_superproject.py b/tests/test_git_superproject.py
index 0ad9b01d..0bb77185 100644
--- a/tests/test_git_superproject.py
+++ b/tests/test_git_superproject.py
@@ -24,6 +24,7 @@ from unittest import mock
 import git_superproject
 import git_trace2_event_log
 import manifest_xml
+import repo_trace
 from test_manifest_xml import sort_attributes
 
 
@@ -39,6 +40,7 @@ class SuperprojectTestCase(unittest.TestCase):
     """Set up superproject every time."""
     self.tempdirobj = tempfile.TemporaryDirectory(prefix='repo_tests')
     self.tempdir = self.tempdirobj.name
+    repo_trace._TRACE_FILE = os.path.join(self.tempdir, 'TRACE_FILE_from_test')
     self.repodir = os.path.join(self.tempdir, '.repo')
     self.manifest_file = os.path.join(
         self.repodir, manifest_xml.MANIFEST_FILE_NAME)
diff --git a/tests/test_manifest_xml.py b/tests/test_manifest_xml.py
index 06328661..f92108e1 100644
--- a/tests/test_manifest_xml.py
+++ b/tests/test_manifest_xml.py
@@ -23,6 +23,7 @@ import xml.dom.minidom
 
 import error
 import manifest_xml
+import repo_trace
 
 
 # Invalid paths that we don't want in the filesystem.
@@ -93,6 +94,7 @@ class ManifestParseTestCase(unittest.TestCase):
   def setUp(self):
     self.tempdirobj = tempfile.TemporaryDirectory(prefix='repo_tests')
     self.tempdir = self.tempdirobj.name
+    repo_trace._TRACE_FILE = os.path.join(self.tempdir, 'TRACE_FILE_from_test')
     self.repodir = os.path.join(self.tempdir, '.repo')
     self.manifest_dir = os.path.join(self.repodir, 'manifests')
     self.manifest_file = os.path.join(
diff --git a/tests/test_project.py b/tests/test_project.py
index acd44ccc..5c600be7 100644
--- a/tests/test_project.py
+++ b/tests/test_project.py
@@ -26,6 +26,7 @@ import git_command
 import git_config
 import platform_utils
 import project
+import repo_trace
 
 
 @contextlib.contextmanager
@@ -64,6 +65,13 @@ class FakeProject(object):
 class ReviewableBranchTests(unittest.TestCase):
   """Check ReviewableBranch behavior."""
 
+  def setUp(self):
+    self.tempdirobj = tempfile.TemporaryDirectory(prefix='repo_tests')
+    repo_trace._TRACE_FILE = os.path.join(self.tempdirobj.name, 'TRACE_FILE_from_test')
+
+  def tearDown(self):
+    self.tempdirobj.cleanup()
+
   def test_smoke(self):
     """A quick run through everything."""
     with TempGitTree() as tempdir: