From 4edb6f78e0ada57c98bb14fcca67d77ff81e64b0 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Mon, 19 Nov 2018 17:09:40 -0500 Subject: [PATCH] redo-log: add automated tests, and fix some path bugs revealed by them. When a log for X was saying it wanted to refer to Y, we used a relative path, but it was sometimes relative to the wrong starting location, so redo-log couldn't find it later. Two examples: - if default.o.do is handling builds for a/b/x.o, and default.o.do does 'redo a/b/x.h', the log for x.o should refer to ./x.h, not a/b/x.h. - if foo.do is handling builds for foo, and it does "cd a/b && redo x", the log for foo should refer to a/b/x, not just x. --- builder.py | 27 +++++++++++++--------- logs.py | 1 + redo-log.py | 33 +++++++++++++++++++-------- state.py | 15 ++++++++++++ t/370-logs/.gitignore | 3 +++ t/370-logs/a/b/xlog.do | 5 ++++ t/370-logs/all.do | 52 ++++++++++++++++++++++++++++++++++++++++++ t/370-logs/clean.do | 1 + t/370-logs/x.do | 5 ++++ t/370-logs/y.do | 3 +++ 10 files changed, 125 insertions(+), 20 deletions(-) create mode 100644 t/370-logs/.gitignore create mode 100644 t/370-logs/a/b/xlog.do create mode 100644 t/370-logs/all.do create mode 100644 t/370-logs/clean.do create mode 100644 t/370-logs/x.do create mode 100644 t/370-logs/y.do diff --git a/builder.py b/builder.py index 490f196..3642ae4 100644 --- a/builder.py +++ b/builder.py @@ -130,7 +130,7 @@ class BuildJob: if not dirty: # target doesn't need to be built; skip the whole task if is_target: - meta('unchanged', _nice(self.t)) + meta('unchanged', state.target_relpath(self.t)) return self._after2(0) except ImmediateReturn, e: return self._after2(e.rv) @@ -200,7 +200,7 @@ class BuildJob: # make sure to create the logfile *before* writing the log about it. # that way redo-log won't trace into an obsolete logfile. if vars.LOG: open(state.logname(self.sf.id), 'w') - meta('do', _nice(t)) + meta('do', state.target_relpath(t)) self.dodir = dodir self.basename = basename self.ext = ext @@ -224,11 +224,14 @@ class BuildJob: # hold onto the lock because otherwise we would introduce a race # condition; that's why it's called redo-unlocked, because it doesn't # grab a lock. - argv = ['redo-unlocked', self.sf.name] + [d.name for d in dirty] - meta('check', _nice(self.t)) + here = os.getcwd() + def _fix(p): + return state.relpath(os.path.join(vars.BASE, p), here) + argv = (['redo-unlocked', _fix(self.sf.name)] + + [_fix(d.name) for d in dirty]) + meta('check', state.target_relpath(self.t)) state.commit() def run(): - os.chdir(vars.BASE) os.environ['REDO_DEPTH'] = vars.DEPTH + ' ' signal.signal(signal.SIGPIPE, signal.SIG_DFL) # python ignores SIGPIPE os.execvp(argv[0], argv) @@ -266,6 +269,7 @@ class BuildJob: # by subprocs, so we'd do nothing. logf = open(state.logname(self.sf.id), 'w') new_inode = str(os.fstat(logf.fileno()).st_ino) + os.environ['REDO_LOG'] = '1' # .do files can check this os.environ['REDO_LOG_INODE'] = new_inode os.dup2(logf.fileno(), 2) close_on_exec(2, False) @@ -273,6 +277,7 @@ class BuildJob: else: if 'REDO_LOG_INODE' in os.environ: del os.environ['REDO_LOG_INODE'] + os.environ['REDO_LOG'] = '' signal.signal(signal.SIGPIPE, signal.SIG_DFL) # python ignores SIGPIPE if vars.VERBOSE or vars.XTRACE: logs.write('* %s' % ' '.join(self.argv).replace('\n', ' ')) @@ -354,7 +359,7 @@ class BuildJob: sf.zap_deps2() sf.save() f.close() - meta('done', '%d %s' % (rv, self.t)) + meta('done', '%d %s' % (rv, state.target_relpath(self.t))) return rv def _after2(self, rv): @@ -427,8 +432,8 @@ def main(targets, shouldbuildfunc): else: lock.trylock() if not lock.owned: - meta('locked', _nice(t)) - locked.append((f.id,t)) + meta('locked', state.target_relpath(t)) + locked.append((f.id,t,f.name)) else: # We had to create f before we had a lock, because we need f.id # to make the lock. But someone may have updated the state @@ -464,7 +469,7 @@ def main(targets, shouldbuildfunc): err('.redo directory disappeared; cannot continue.\n') retcode[0] = 205 break - fid,t = locked.pop(0) + fid,t,fname = locked.pop(0) lock = state.Lock(fid) backoff = 0.01 lock.trylock() @@ -475,7 +480,7 @@ def main(targets, shouldbuildfunc): backoff *= 2 # after printing this line, redo-log will recurse into t, # whether it's us building it, or someone else. - meta('waiting', _nice(t)) + meta('waiting', state.target_relpath(t)) try: lock.check() except state.CyclicDependencyError: @@ -494,7 +499,7 @@ def main(targets, shouldbuildfunc): jwack.ensure_token_or_cheat(t, cheat) lock.trylock() assert(lock.owned) - meta('unlocked', _nice(t)) + meta('unlocked', state.target_relpath(t)) if state.File(name=t).is_failed(): err('%s: failed in another thread\n' % _nice(t)) retcode[0] = 2 diff --git a/logs.py b/logs.py index 54a17ee..2ef1448 100644 --- a/logs.py +++ b/logs.py @@ -37,6 +37,7 @@ REDO_RE = re.compile(r'@@REDO:([^@]+)@@ (.*)$') class PrettyLog(object): def __init__(self, file): + self.topdir = os.getcwd() self.file = file def _pretty(self, pid, color, s): diff --git a/redo-log.py b/redo-log.py index 1026175..c29fbc8 100755 --- a/redo-log.py +++ b/redo-log.py @@ -26,6 +26,7 @@ vars_init.init(list(targets)) import vars, logs, state +topdir = os.getcwd() already = set() queue = [] depth = [] @@ -68,6 +69,10 @@ def _fix_depth(): vars.DEPTH = len(depth) * ' ' +def _rel(topdir, mydir, path): + return os.path.relpath(os.path.join(topdir, mydir, path), topdir) + + def catlog(t): global total_lines, status if t in already: @@ -76,6 +81,7 @@ def catlog(t): depth.append(t) _fix_depth() already.add(t) + mydir = os.path.dirname(t) if t == '-': f = sys.stdin fid = None @@ -85,7 +91,8 @@ def catlog(t): try: sf = state.File(name=t, allow_add=False) except KeyError: - sys.stderr.write('redo-log: %r: not known to redo.\n' % (t,)) + sys.stderr.write('redo-log: [%s] %r: not known to redo.\n' + % (os.getcwd(), t,)) sys.exit(24) fid = sf.id del sf @@ -168,26 +175,34 @@ def catlog(t): words, text = g.groups() kind, pid, when = words.split(':')[0:3] pid = atoi(pid) + relname = _rel(topdir, mydir, text) + fixname = os.path.normpath(os.path.join(mydir, text)) if kind == 'unchanged': if opt.unchanged: if opt.debug_locks: - logs.write(line.rstrip()) - elif text not in already: - logs.meta('do', text, pid=pid) + logs.meta(kind, relname, pid=pid) + elif fixname not in already: + logs.meta('do', relname, pid=pid) if opt.recursive: if loglock: loglock.unlock() - catlog(text) + catlog(os.path.join(mydir, text)) if loglock: loglock.waitlock(shared=True) + already.add(fixname) elif kind in ('do', 'waiting', 'locked', 'unlocked'): if opt.debug_locks: + logs.meta(kind, relname, pid=pid) logs.write(line.rstrip()) - elif text not in already: - logs.meta('do', text, pid=pid) + elif fixname not in already: + logs.meta('do', relname, pid=pid) if opt.recursive: assert text if loglock: loglock.unlock() - catlog(text) + catlog(os.path.join(mydir, text)) if loglock: loglock.waitlock(shared=True) + already.add(fixname) + elif kind == 'done': + rv, name = text.split(' ', 1) + logs.meta(kind, rv + ' ' + _rel(topdir, mydir, name)) else: logs.write(line.rstrip()) else: @@ -231,7 +246,7 @@ try: while queue: t = queue.pop(0) if t != '-': - logs.meta('do', t, pid=0) + logs.meta('do', _rel(topdir, '.', t), pid=0) catlog(t) except KeyboardInterrupt: sys.exit(200) diff --git a/state.py b/state.py index 4556e68..9799748 100644 --- a/state.py +++ b/state.py @@ -165,6 +165,21 @@ def relpath(t, base): return join('/', tparts) +# Return a path for t, if cwd were the dirname of vars.TARGET. +# This is tricky! STARTDIR+PWD is the directory for the *dofile*, when +# the dofile was started. However, inside the dofile, someone may have done +# a chdir to anywhere else. vars.TARGET is relative to the dofile path, so +# we have to first figure out where the dofile was, then find TARGET relative +# to that, then find t relative to that. +# +# FIXME: find some cleaner terminology for all these different paths. +def target_relpath(t): + dofile_dir = os.path.abspath(os.path.join(vars.STARTDIR, vars.PWD)) + target_dir = os.path.abspath( + os.path.dirname(os.path.join(dofile_dir, vars.TARGET))) + return relpath(t, target_dir) + + def warn_override(name): warn('%s - you modified it; skipping\n' % name) diff --git a/t/370-logs/.gitignore b/t/370-logs/.gitignore new file mode 100644 index 0000000..0f2067e --- /dev/null +++ b/t/370-logs/.gitignore @@ -0,0 +1,3 @@ +pid +x +y diff --git a/t/370-logs/a/b/xlog.do b/t/370-logs/a/b/xlog.do new file mode 100644 index 0000000..225dfa0 --- /dev/null +++ b/t/370-logs/a/b/xlog.do @@ -0,0 +1,5 @@ +read pid <../../pid + +# Test that log retrieval works correctly when run from a different base dir. +redo-log -ru ../../x | grep -q "^$pid x stderr" || exit 45 +redo-log -ru ../../x | grep -q "^$pid y stderr" || exit 46 diff --git a/t/370-logs/all.do b/t/370-logs/all.do new file mode 100644 index 0000000..5154858 --- /dev/null +++ b/t/370-logs/all.do @@ -0,0 +1,52 @@ +exec >&2 +rm -f x pid +pid=$$ +echo "$pid" >pid +xout=$(redo x) + +[ "$(printf "$xout" | wc -l)" -eq 0 ] || exit 2 + +if [ -n "$REDO_LOG" ]; then + # redo has redo-log support enabled, so check that it saves logs. + + # recursive log dump should show both x and y stderr. + redo-log -ru x | grep -q "^$pid x stderr" || exit 10 + redo-log -ru x | grep -q "^$pid y stderr" || exit 11 + + # stdout captured by redo into the files x and y, *not* to log + redo-log -ru x | grep -q "^$pid x stdout" && exit 20 + redo-log -ru x | grep -q "^$pid y stdout" && exit 21 + [ "$(cat x)" = "$pid x stdout" ] || exit 22 + [ "$(cat y)" = "$pid y stdout" ] || exit 23 + + # non-recursive log dump of x should *not* include y + redo-log x | grep -q "^$pid y stdout" && exit 30 + redo-log x | grep -q "^$pid y stderr" && exit 31 + + redo a/b/xlog + (cd a && redo b/xlog) + + # Test retrieval from a different $PWD. + ( + cd a/b || exit 40 + redo-log -ru ../../x | grep -q "^$pid x stderr" || exit 41 + redo-log -ru ../../x | grep -q "^$pid y stderr" || exit 42 + ) || exit +fi + +# whether or not redo-log is available, redirecting stderr should work. +pid=$$-bork +rm -f x pid +echo "$pid" >pid +out=$(redo x 2>&1) + +# x's stderr should obviously go where we sent it +echo "$out" | grep -q "^$pid x stderr" || exit 50 + +# This one is actually tricky: with redo-log, x's call to 'redo y' would +# normally implicitly redirect y's stderr to a new log. redo needs to +# detect that we've already redirected it where we want, and not take it +# away. +echo "$out" | grep -q "^$pid y stderr" || exit 51 + +exit 0 diff --git a/t/370-logs/clean.do b/t/370-logs/clean.do new file mode 100644 index 0000000..614b745 --- /dev/null +++ b/t/370-logs/clean.do @@ -0,0 +1 @@ +rm -f *~ .*~ all x y pid diff --git a/t/370-logs/x.do b/t/370-logs/x.do new file mode 100644 index 0000000..9512abd --- /dev/null +++ b/t/370-logs/x.do @@ -0,0 +1,5 @@ +read pid &2 +rm -f y +redo y diff --git a/t/370-logs/y.do b/t/370-logs/y.do new file mode 100644 index 0000000..c754109 --- /dev/null +++ b/t/370-logs/y.do @@ -0,0 +1,3 @@ +read pid &2