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.
This commit is contained in:
Avery Pennarun 2018-11-19 17:09:40 -05:00
commit 4edb6f78e0
10 changed files with 125 additions and 20 deletions

View file

@ -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

View file

@ -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):

View file

@ -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)

View file

@ -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)

3
t/370-logs/.gitignore vendored Normal file
View file

@ -0,0 +1,3 @@
pid
x
y

5
t/370-logs/a/b/xlog.do Normal file
View file

@ -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

52
t/370-logs/all.do Normal file
View file

@ -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

1
t/370-logs/clean.do Normal file
View file

@ -0,0 +1 @@
rm -f *~ .*~ all x y pid

5
t/370-logs/x.do Normal file
View file

@ -0,0 +1,5 @@
read pid <pid
echo "$pid x stdout"
echo "$pid x stderr" >&2
rm -f y
redo y

3
t/370-logs/y.do Normal file
View file

@ -0,0 +1,3 @@
read pid <pid
echo "$pid y stdout"
echo "$pid y stderr" >&2