Set tracing to always on and save to .repo/TRACE_FILE.

- add `--trace_to_stderr` option so stderr will include trace outputs and any other errors that get sent to stderr
- while TRACE_FILE will only include trace outputs

piggy-backing on: https://gerrit-review.googlesource.com/c/git-repo/+/349154

Change-Id: I3895a84de4b2784f17fac4325521cd5e72e645e2
Reviewed-on: https://gerrit-review.googlesource.com/c/git-repo/+/350114
Reviewed-by: LaMont Jones <lamontjones@google.com>
Tested-by: Joanna Wang <jojwang@google.com>

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,8 +262,8 @@ class GitCommand(object):
         dbg += ' 2>|'
       elif stderr == subprocess.STDOUT:
         dbg += ' 2>&1'
-      Trace('%s', dbg)
 
+    with Trace('git command %s %s with debug: %s', LAST_GITDIR, command, dbg):
       try:
         p = subprocess.Popen(command,
                             cwd=cwd,

git_config.py

@@ -349,7 +349,7 @@ class GitConfig(object):
     except OSError:
       return None
     try:
-      Trace(': parsing %s', self.file)
+      with Trace(': parsing %s', self.file):
         with open(self._json) as fd:
           return json.load(fd)
     except (IOError, ValueError):

git_refs.py

@@ -67,8 +67,7 @@ class GitRefs(object):
       self._LoadAll()
 
   def _NeedUpdate(self):
-    Trace(': scan refs %s', self._gitdir)
+    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)):
@@ -78,7 +77,7 @@ class GitRefs(object):
       return False
 
   def _LoadAll(self):
-    Trace(': load refs %s', self._gitdir)
+    with Trace(': load refs %s', self._gitdir):
 
       self._phyref = {}
       self._symref = {}

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,9 +652,18 @@ def _Main(argv):
   Version.wrapper_path = opt.wrapper_path
 
   repo = _Repo(opt.repodir)
+
   try:
     init_http()
     name, gopts, argv = repo._ParseArgs(argv)
+
+    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

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,8 +2416,8 @@ class Project(object):
         srcUrl = 'http' + srcUrl[len('persistent-http'):]
       cmd += [srcUrl]
 
-      if IsTrace():
+      proc = None
-        Trace('%s', ' '.join(cmd))
+      with Trace('Fetching bundle: %s', ' '.join(cmd)):
         if verbose:
           print('%s: Downloading bundle: %s' % (self.name, srcUrl))
         stdout = None if verbose else subprocess.PIPE

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):
+def _SetTraceFile():
-  if IsTrace():
+  global _TRACE_FILE
-    print(fmt % args, file=sys.stderr)
+  _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)

run_tests

@@ -20,6 +20,7 @@ import os
 import shutil
 import subprocess
 import sys
+import repo_trace
 
 
 def find_pytest():

ssh.py

@@ -182,8 +182,8 @@ 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']
+    with Trace('Call to ssh (check call): %s', ' '.join(check_command)):
       try:
-      Trace(': %s', ' '.join(check_command))
         check_process = subprocess.Popen(check_command,
                                         stdout=subprocess.PIPE,
                                         stderr=subprocess.PIPE)
@@ -196,13 +196,14 @@ class ProxyManager:
           self._master_keys[key] = True
           return True
       except Exception:
-      # Ignore excpetions.  We we will fall back to the normal command and print
+        # Ignore excpetions.  We we will fall back to the normal command and
-      # to the log there.
+        # print to the log there.
         pass
 
     command = command_base[:1] + ['-M', '-N'] + command_base[1:]
+    p = None
     try:
-      Trace(': %s', ' '.join(command))
+      with Trace('Call to ssh: %s', ' '.join(command)):
         p = subprocess.Popen(command)
     except Exception as e:
       self._master_broken.value = True

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)
+        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)
-    if saved:
-      Trace('%s saved %s', bare_git._project.name, ' '.join(saved))
 
   def _GCProjects(self, projects, opt, err_event):
     pm = Progress('Garbage collecting', len(projects), delay=False, quiet=opt.quiet)

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)

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)

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(

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: