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)) + 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 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) + 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 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() + 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 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: