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>
diff --git a/git_command.py b/git_command.py
index 19100fa..56e18e0 100644
--- a/git_command.py
+++ b/git_command.py
@@ -230,12 +230,11 @@
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 @@
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))
+ 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))
- if ssh_proxy:
- 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()
+ 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 6f80ae0..98cade3 100644
--- a/git_config.py
+++ b/git_config.py
@@ -349,9 +349,9 @@
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 2d4a809..300d2b3 100644
--- a/git_refs.py
+++ b/git_refs.py
@@ -67,38 +67,37 @@
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)
+ with Trace(': load refs %s', self._gitdir):
- self._phyref = {}
- self._symref = {}
- self._mtime = {}
+ self._phyref = {}
+ self._symref = {}
+ self._mtime = {}
- self._ReadPackedRefs()
- self._ReadLoose('refs/')
- self._ReadLoose1(os.path.join(self._gitdir, HEAD), HEAD)
+ 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
+ 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 c54f928..e629b30 100755
--- a/main.py
+++ b/main.py
@@ -37,7 +37,7 @@
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('--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 @@
"""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 @@
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 1c85b04..b975b72 100644
--- a/project.py
+++ b/project.py
@@ -41,7 +41,7 @@
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 @@
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 7be0c04..0ff3b69 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 573dd44..7c9ff41 100755
--- a/run_tests
+++ b/run_tests
@@ -20,6 +20,7 @@
import shutil
import subprocess
import sys
+import repo_trace
def find_pytest():
diff --git a/ssh.py b/ssh.py
index 450383d..004fdba 100644
--- a/ssh.py
+++ b/ssh.py
@@ -182,28 +182,29 @@
# 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()
+ 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
+ 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 fe63b48..082b254 100644
--- a/subcmds/sync.py
+++ b/subcmds/sync.py
@@ -60,7 +60,7 @@
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 @@
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 @@
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 a4fad9e..0df3843 100644
--- a/tests/test_git_config.py
+++ b/tests/test_git_config.py
@@ -19,6 +19,7 @@
import unittest
import git_config
+import repo_trace
def fixture(*paths):
@@ -33,9 +34,16 @@
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 @@
"""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 0ad9b01..0bb7718 100644
--- a/tests/test_git_superproject.py
+++ b/tests/test_git_superproject.py
@@ -24,6 +24,7 @@
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 @@
"""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 0632866..f92108e 100644
--- a/tests/test_manifest_xml.py
+++ b/tests/test_manifest_xml.py
@@ -23,6 +23,7 @@
import error
import manifest_xml
+import repo_trace
# Invalid paths that we don't want in the filesystem.
@@ -93,6 +94,7 @@
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 acd44cc..5c600be 100644
--- a/tests/test_project.py
+++ b/tests/test_project.py
@@ -26,6 +26,7 @@
import git_config
import platform_utils
import project
+import repo_trace
@contextlib.contextmanager
@@ -64,6 +65,13 @@
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:
