diff --git a/Documentation/redo-log.md b/Documentation/redo-log.md new file mode 100644 index 0000000..cd6af0c --- /dev/null +++ b/Documentation/redo-log.md @@ -0,0 +1,83 @@ +# NAME + +redo-log - display log messages from previous builds + +# SYNOPSIS + +redo-log [options...] [targets...] + + +# DESCRIPTION + +When redo runs, it captures the standard error (stderr) output from the +build activity for each target, and saves it for later. When a target is +rebuilt, the new logs replace the old logs for that target. redo-log +prints the log output for any set of targets. + +# OPTIONS + +-r, --recursive +: if the requested targets cause any dependencies to be built, recursively + show the logs from those dependencies as well. (And if those + dependencies build further dependencies, also show those logs, and so on.) + +-u, --unchanged +: show messages even for dependencies that were unchanged (did not need to be + rebuilt). To do this, we show the logs for the *most recent* build of + each affected dependency. Usually this is used with `-r`. + +-f, --follow +: if a build is currently running for any of the requested targets or + their dependencies, follow the logs (like `tail -f`) until the build + finishes. + +--no-details +: display *only* the messages from redo itself, not the other messages + produced by build scripts. Generally this gives you a list of which + targets were built, but not detailed logs, warnings, or errors. + +--no-status +: don't display the running build status at the bottom of the screen. + (Unless this option is specified, the status line will be enabled + if using --follow, if stderr is a terminal.) If stderr is *not* a + terminal, you can force enable the status line using --status. + +--no-pretty +: display "raw" redo log lines (@@REDO events) rather than using a + human-readable format. The default is --pretty. + +--no-color +: when using --pretty and writing to a terminal, colorize the output to + make results stand out more clearly. If not writing to a terminal, you + can use --color to force colorized output. + +--debug-locks +: print messages about acquiring, releasing, and waiting + on locks. Because redo can be highly parallelized, + one instance may end up waiting for a target to be + built by some other instance before it can continue. + If you suspect this is causing troubles, use this + option to see which instance is waiting and when. + +--debug-pids +: add the process id of the particular redo instance to each + output message. This makes it easier to figure out + which sub-instance of redo is doing what. + + +# REDO + +Part of the `redo`(1) suite. + +# CREDITS + +The original concept for `redo` was created by D. J. +Bernstein and documented on his web site +(http://cr.yp.to/redo.html). This independent implementation +was created by Avery Pennarun and you can find its source +code at http://github.com/apenwarr/redo. + + +# SEE ALSO + +`redo`(1) diff --git a/Documentation/redo.md b/Documentation/redo.md index e508ada..b98d189 100644 --- a/Documentation/redo.md +++ b/Documentation/redo.md @@ -86,6 +86,32 @@ dependencies. can just run three `redo` commands consecutively. Because your .do script is just a script, it will not be accidentally parallelized. + +--no-details +: display *only* the messages from redo itself, not the other messages + produced by build scripts. Generally this gives you a list of which + targets were built, but not detailed logs, warnings, or errors. + +--no-status +: don't display the running build status at the bottom of the screen. + (Unless this option is specified, the status line will be enabled + if using --follow, if stderr is a terminal.) If stderr is *not* a + terminal, you can force enable the status line using --status. + +--no-pretty +: display "raw" redo log lines (@@REDO events) rather than using a + human-readable format. The default is --pretty. + +--no-color +: when using --pretty and writing to a terminal, colorize the output to + make results stand out more clearly. If not writing to a terminal, you + can use --color to force colorized output. + +--no-log +: don't capture stderr log messages from build scripts. This prevents + redo-log from redisplaying the logs later, and if using --jobs, causes + output from all parallel jobs to be jumbled together. This was the + only behaviour available before redo-0.30. The default is --log. --debug-locks : print messages about acquiring, releasing, and waiting @@ -100,6 +126,9 @@ dependencies. output message. This makes it easier to figure out which sub-instance of redo is doing what. +--version +: displays the redo version number. + # DISCUSSION diff --git a/builder.py b/builder.py index 4cc0fc8..3642ae4 100644 --- a/builder.py +++ b/builder.py @@ -1,7 +1,8 @@ import sys, os, errno, random, stat, signal, time import vars, jwack, state, paths from helpers import unlink, close_on_exec, join -from log import log, log_, debug, debug2, err, warn +import logs +from logs import debug, debug2, err, warn, meta, check_tty def _nice(t): @@ -18,6 +19,84 @@ def _try_stat(filename): raise +log_reader_pid = None + + +def start_stdin_log_reader(status, details, pretty, color, + debug_locks, debug_pids): + if not vars.LOG: return + global log_reader_pid + r, w = os.pipe() # main pipe to redo-log + ar, aw = os.pipe() # ack pipe from redo-log --ack-fd + sys.stdout.flush() + sys.stderr.flush() + pid = os.fork() + if pid: + # parent + log_reader_pid = pid + os.close(r) + os.close(aw) + b = os.read(ar, 8) + if not b: + # subprocess died without sending us anything: that's bad. + err('failed to start redo-log subprocess; cannot continue.\n') + os._exit(99) + assert b == 'REDO-OK\n' + # now we know the subproc is running and will report our errors + # to stderr, so it's okay to lose our own stderr. + os.close(ar) + os.dup2(w, 1) + os.dup2(w, 2) + os.close(w) + check_tty(sys.stderr, vars.COLOR) + else: + # child + try: + os.close(ar) + os.close(w) + os.dup2(r, 0) + os.close(r) + # redo-log sends to stdout (because if you ask for logs, that's + # the output you wanted!). But redo itself sends logs to stderr + # (because they're incidental to the thing you asked for). + # To make these semantics work, we point redo-log's stdout at + # our stderr when we launch it. + os.dup2(2, 1) + argv = [ + 'redo-log', + '--recursive', '--follow', + '--ack-fd', str(aw), + ('--status' if status and os.isatty(2) else '--no-status'), + ('--details' if details else '--no-details'), + ('--pretty' if pretty else '--no-pretty'), + ('--debug-locks' if debug_locks else '--no-debug-locks'), + ('--debug-pids' if debug_pids else '--no-debug-pids'), + ] + if color != 1: + argv.append('--color' if color >= 2 else '--no-color') + argv.append('-') + os.execvp(argv[0], argv) + except Exception, e: + sys.stderr.write('redo-log: exec: %s\n' % e) + finally: + os._exit(99) + + +def await_log_reader(): + if not vars.LOG: return + global log_reader_pid + if log_reader_pid > 0: + # never actually close fd#1 or fd#2; insanity awaits. + # replace it with something else instead. + # Since our stdout/stderr are attached to redo-log's stdin, + # this will notify redo-log that it's time to die (after it finishes + # reading the logs) + out = open('/dev/tty', 'w') + os.dup2(out.fileno(), 1) + os.dup2(out.fileno(), 2) + os.waitpid(log_reader_pid, 0) + + class ImmediateReturn(Exception): def __init__(self, rv): Exception.__init__(self, "immediate return with exit code %d" % rv) @@ -44,12 +123,14 @@ class BuildJob: assert(self.lock.owned) try: try: - dirty = self.shouldbuildfunc(self.t) + is_target, dirty = self.shouldbuildfunc(self.t) except state.CyclicDependencyError: err('cyclic dependency while checking %s\n' % _nice(self.t)) raise ImmediateReturn(208) if not dirty: # target doesn't need to be built; skip the whole task + if is_target: + meta('unchanged', state.target_relpath(self.t)) return self._after2(0) except ImmediateReturn, e: return self._after2(e.rv) @@ -94,7 +175,7 @@ class BuildJob: sf.save() return self._after2(0) else: - err('no rule to make %r\n' % t) + err('no rule to redo %r\n' % t) return self._after2(1) unlink(self.tmpname1) unlink(self.tmpname2) @@ -113,11 +194,13 @@ class BuildJob: ] if vars.VERBOSE: argv[1] += 'v' if vars.XTRACE: argv[1] += 'x' - if vars.VERBOSE or vars.XTRACE: log_('\n') firstline = open(os.path.join(dodir, dofile)).readline().strip() if firstline.startswith('#!/'): argv[0:2] = firstline[2:].split(' ') - log('%s\n' % _nice(t)) + # 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', state.target_relpath(t)) self.dodir = dodir self.basename = basename self.ext = ext @@ -141,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] - log('(%s)\n' % _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) @@ -173,9 +259,32 @@ class BuildJob: os.dup2(self.f.fileno(), 1) os.close(self.f.fileno()) close_on_exec(1, False) + if vars.LOG: + cur_inode = str(os.fstat(2).st_ino) + if not vars.LOG_INODE or cur_inode == vars.LOG_INODE: + # .do script has *not* redirected stderr, which means we're + # using redo-log's log saving mode. That means subprocs + # should be logged to their own file. If the .do script + # *does* redirect stderr, that redirection should be inherited + # 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) + logf.close() + 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: log_('* %s\n' % ' '.join(self.argv)) + if vars.VERBOSE or vars.XTRACE: + logs.write('* %s' % ' '.join(self.argv).replace('\n', ' ')) os.execvp(self.argv[0], self.argv) + # FIXME: it would be nice to log the exit code to logf. + # But that would have to happen in the parent process, which doesn't + # have logf open. assert(0) # returns only if there's an exception @@ -250,11 +359,7 @@ class BuildJob: sf.zap_deps2() sf.save() f.close() - if rv != 0: - err('%s: exit code %r\n' % (_nice(t),rv)) - else: - if vars.VERBOSE or vars.XTRACE or vars.DEBUG: - log('%s (done)\n\n' % _nice(t)) + meta('done', '%d %s' % (rv, state.target_relpath(self.t))) return rv def _after2(self, rv): @@ -276,6 +381,27 @@ def main(targets, shouldbuildfunc): def done(t, rv): if rv: retcode[0] = 1 + + if vars.TARGET and not vars.UNLOCKED: + me = os.path.join(vars.STARTDIR, + os.path.join(vars.PWD, vars.TARGET)) + myfile = state.File(name=me) + selflock = state.Lock(state.LOG_LOCK_MAGIC + myfile.id) + else: + selflock = myfile = me = None + + def cheat(): + if not selflock: return 0 + selflock.trylock() + if not selflock.owned: + # redo-log already owns it: let's cheat. + # Give ourselves one extra token so that the "foreground" log + # can always make progress. + return 1 + else: + # redo-log isn't watching us (yet) + selflock.unlock() + return 0 # In the first cycle, we just build as much as we can without worrying # about any lock contention. If someone else has it locked, we move on. @@ -292,7 +418,7 @@ def main(targets, shouldbuildfunc): seen[t] = 1 if not jwack.has_token(): state.commit() - jwack.get_token(t) + jwack.ensure_token_or_cheat(t, cheat) if retcode[0] and not vars.KEEP_GOING: break if not state.check_sane(): @@ -306,9 +432,8 @@ def main(targets, shouldbuildfunc): else: lock.trylock() if not lock.owned: - if vars.DEBUG_LOCKS: - log('%s (locked...)\n' % _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 @@ -333,6 +458,8 @@ def main(targets, shouldbuildfunc): while locked or jwack.running(): state.commit() jwack.wait_all() + assert jwack._mytokens == 0 + jwack.ensure_token_or_cheat('self', cheat) # at this point, we don't have any children holding any tokens, so # it's okay to block below. if retcode[0] and not vars.KEEP_GOING: @@ -342,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() @@ -351,8 +478,9 @@ def main(targets, shouldbuildfunc): import random time.sleep(random.random() * min(backoff, 1.0)) backoff *= 2 - if vars.DEBUG_LOCKS: - warn('%s (WAITING)\n' % _nice(t)) + # after printing this line, redo-log will recurse into t, + # whether it's us building it, or someone else. + meta('waiting', state.target_relpath(t)) try: lock.check() except state.CyclicDependencyError: @@ -361,16 +489,17 @@ def main(targets, shouldbuildfunc): return retcode[0] # this sequence looks a little silly, but the idea is to # give up our personal token while we wait for the lock to - # be released; but we should never run get_token() while + # be released; but we should never run ensure_token() while # holding a lock, or we could cause deadlocks. jwack.release_mine() lock.waitlock() + # now t is definitely free, so we get to decide whether + # to build it. lock.unlock() - jwack.get_token(t) + jwack.ensure_token_or_cheat(t, cheat) lock.trylock() assert(lock.owned) - if vars.DEBUG_LOCKS: - log('%s (...unlocked!)\n' % _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/clean.do b/clean.do index 694c6b2..ed3fc5e 100644 --- a/clean.do +++ b/clean.do @@ -6,7 +6,7 @@ if [ -e .do_built ]; then done <.do_built fi [ -z "$DO_BUILT" ] && rm -rf .do_built .do_built.dir -rm -rf minimal/.do_built minimal/.do_built.dir +rm -rf minimal/.do_built minimal/.do_built.dir website redo t/clean Documentation/clean version/clean rm -f *~ .*~ */*~ */.*~ *.pyc install.wrapper find . -name '*.tmp' -exec rm -fv {} \; diff --git a/deps.py b/deps.py index dd658c5..d2ac6a2 100644 --- a/deps.py +++ b/deps.py @@ -1,6 +1,6 @@ import sys, os import vars, state, builder -from log import debug +from logs import debug CLEAN = 0 DIRTY = 1 diff --git a/jwack.py b/jwack.py index 80786b4..1aaf432 100644 --- a/jwack.py +++ b/jwack.py @@ -1,42 +1,150 @@ # -# beware the jobberwack +# Implementation of a GNU make-compatible jobserver. +# +# The basic idea is that both ends of a pipe (tokenfds) are shared with all +# subprocesses. At startup, we write one "token" into the pipe for each +# configured job. (So eg. redo -j20 will put 20 tokens in the pipe.) In +# order to do work, you must first obtain a token, by reading the other +# end of the pipe. When you're done working, you write the token back into +# the pipe so that someone else can grab it. +# +# The toplevel process in the hierarchy is what creates the pipes in the +# first place. Then it puts the pipe file descriptor numbers into MAKEFLAGS, +# so that subprocesses can pull them back out. +# +# As usual, edge cases make all this a bit tricky: +# +# - Every process is defined as owning a token at startup time. This makes +# sense because it's backward compatible with single-process make: if a +# subprocess neither reads nor writes the pipe, then it has exactly one +# token, so it's allowed to do one thread of work. +# +# - Thus, for symmetry, processes also must own a token at exit time. +# +# - In turn, to make *that* work, a parent process must destroy *its* token +# upon launching a subprocess. (Destroy, not release, because the +# subprocess has created its own token.) It can try to obtain another +# token, but if none are available, it has to stop work until one of its +# subprocesses finishes. When the subprocess finishes, its token is +# destroyed, so the parent creates a new one. +# +# - If our process is going to stop and wait for a lock (eg. because we +# depend on a target and someone else is already building that target), +# we must give up our token. Otherwise, we're sucking up a "thread" (a +# unit of parallelism) just to do nothing. If enough processes are waiting +# on a particular lock, then the process building that target might end up +# with only a single token, and everything gets serialized. +# +# - Unfortunately this leads to a problem: if we give up our token, we then +# have to re-acquire a token before exiting, even if we want to exit with +# an error code. +# +# - redo-log wants to linearize output so that it always prints log messages +# in the order jobs were started; but because of the above, a job being +# logged might end up with no tokens for a long time, waiting for some +# other branch of the build to complete. +# +# As a result, we extend beyond GNU make's model and make things even more +# complicated. We add a second pipe, cheatfds, which we use to "cheat" on +# tokens if our particular job is in the foreground (ie. is the one +# currently being tailed by redo-log -f). We add at most one token per +# redo-log instance. If we are the foreground task, and we need a token, +# and we don't have a token, and we don't have any subtasks (because if we +# had a subtask, then we're not in the foreground), we synthesize our own +# token by incrementing _mytokens and _cheats, but we don't read from +# tokenfds. Then, when it's time to give up our token again, we also won't +# write back to tokenfds, so the synthesized token disappears. +# +# Of course, all that then leads to *another* problem: every process must +# hold a *real* token when it exits, because its parent has given up a +# *real* token in order to start this subprocess. If we're holding a cheat +# token when it's time to exit, then we can't meet this requirement. The +# obvious thing to do would be to give up the cheat token and wait for a +# real token, but that might take a very long time, and if we're the last +# thing preventing our parent from exiting, then redo-log will sit around +# following our parent until we finally get a token so we can exit, +# defeating the whole purpose of cheating. Instead of waiting, we write our +# "cheater" token to cheatfds. Then, any task, upon noticing one of its +# subprocesses has finished, will check to see if there are any tokens on +# cheatfds; if so, it will remove one of them and *not* re-create its +# child's token, thus destroying the cheater token from earlier, and restoring +# balance. +# +# Sorry this is so complicated. I couldn't think of a way to make it +# simpler :) # import sys, os, errno, select, fcntl, signal from helpers import atoi, close_on_exec -import state +import state, vars _toplevel = 0 _mytokens = 1 -_fds = None +_cheats = 0 +_tokenfds = None +_cheatfds = None _waitfds = {} def _debug(s): if 0: sys.stderr.write('jwack#%d: %s' % (os.getpid(),s)) - + + +def _create_tokens(n): + global _mytokens, _cheats + assert n >= 0 + assert _cheats >= 0 + for _ in xrange(n): + if _cheats > 0: + _cheats -= 1 + else: + _mytokens += 1 + + +def _destroy_tokens(n): + global _mytokens + assert _mytokens >= n + _mytokens -= n + def _release(n): - global _mytokens - _mytokens += n - _debug('release(%d) -> %d\n' % (n, _mytokens)) - if _mytokens > 1: - os.write(_fds[1], 't' * (_mytokens-1)) - _mytokens = 1 + global _mytokens, _cheats + assert n >= 0 + assert _mytokens >= n + _debug('%d,%d -> release(%d)\n' % (_mytokens, _cheats, n)) + n_to_share = 0 + for _ in xrange(n): + _mytokens -= 1 + if _cheats > 0: + _cheats -= 1 + else: + n_to_share += 1 + assert _mytokens >= 0 + assert _cheats >= 0 + if n_to_share: + _debug('PUT tokenfds %d\n' % n_to_share) + os.write(_tokenfds[1], 't' * n_to_share) + + +def _release_except_mine(): + assert _mytokens > 0 + _release(_mytokens - 1) def release_mine(): global _mytokens - assert(_mytokens >= 1) - _mytokens -= 1 - _debug('release_mine() -> %d\n' % _mytokens) - os.write(_fds[1], 't') + assert _mytokens >= 1 + _debug('%d,%d -> release_mine()\n' % (_mytokens, _cheats)) + _release(1) def _timeout(sig, frame): pass +# We make the pipes use the first available fd numbers starting at startfd. +# This makes it easier to differentiate different kinds of pipes when using +# strace. def _make_pipe(startfd): (a,b) = os.pipe() fds = (fcntl.fcntl(a, fcntl.F_DUPFD, startfd), @@ -47,38 +155,51 @@ def _make_pipe(startfd): def _try_read(fd, n): + """Try to read n bytes from fd. Returns: '' on EOF, None if EAGAIN.""" + assert state.is_flushed() + # using djb's suggested way of doing non-blocking reads from a blocking # socket: http://cr.yp.to/unix/nonblock.html # We can't just make the socket non-blocking, because we want to be # compatible with GNU Make, and they can't handle it. r,w,x = select.select([fd], [], [], 0) if not r: - return '' # try again + return None # try again # ok, the socket is readable - but some other process might get there # first. We have to set an alarm() in case our read() gets stuck. - assert(state.is_flushed()) oldh = signal.signal(signal.SIGALRM, _timeout) try: - signal.alarm(1) # emergency fallback + signal.setitimer(signal.ITIMER_REAL, 0.01, 0.01) # emergency fallback try: - b = os.read(_fds[0], 1) + b = os.read(fd, 1) except OSError, e: if e.errno in (errno.EAGAIN, errno.EINTR): # interrupted or it was nonblocking - return '' # try again + return None # try again else: raise finally: - signal.alarm(0) + signal.setitimer(signal.ITIMER_REAL, 0, 0) signal.signal(signal.SIGALRM, oldh) - return b and b or None # None means EOF + return b + + +def _try_read_all(fd, n): + bb = '' + while 1: + b = _try_read(fd, n) + if not b: + break + bb += b + return bb def setup(maxjobs): - global _fds, _toplevel - if _fds: - return # already set up + global _tokenfds, _cheatfds, _toplevel + assert maxjobs > 0 + assert not _tokenfds _debug('setup(%d)\n' % maxjobs) + flags = ' ' + os.getenv('MAKEFLAGS', '') + ' ' FIND1 = ' --jobserver-auth=' # renamed in GNU make 4.2 FIND2 = ' --jobserver-fds=' # fallback syntax @@ -103,38 +224,64 @@ def setup(maxjobs): raise ValueError('broken --jobserver-auth from make; prefix your Makefile rule with a "+"') else: raise - _fds = (a,b) - if maxjobs and not _fds: + _tokenfds = (a,b) + + cheats = os.getenv('REDO_CHEATFDS', '') + if cheats: + (a,b) = cheats.split(',', 1) + a = atoi(a) + b = atoi(b) + if a <= 0 or b <= 0: + raise ValueError('invalid REDO_CHEATFDS: %r' % cheats) + _cheatfds = (a,b) + + if not _tokenfds: # need to start a new server _toplevel = maxjobs - _fds = _make_pipe(100) - _release(maxjobs-1) + _tokenfds = _make_pipe(100) + _create_tokens(maxjobs - 1) + _release_except_mine() os.putenv('MAKEFLAGS', '%s -j --jobserver-auth=%d,%d --jobserver-fds=%d,%d' % (os.getenv('MAKEFLAGS', ''), - _fds[0], _fds[1], - _fds[0], _fds[1])) + _tokenfds[0], _tokenfds[1], + _tokenfds[0], _tokenfds[1])) + _cheatfds = _make_pipe(102) + os.putenv('REDO_CHEATFDS', '%d,%d' % (_cheatfds[0], _cheatfds[1])) -def wait(want_token): +def _wait(want_token, max_delay): rfds = _waitfds.keys() - if _fds and want_token: - rfds.append(_fds[0]) - assert(rfds) - assert(state.is_flushed()) - r,w,x = select.select(rfds, [], []) - _debug('_fds=%r; wfds=%r; readable: %r\n' % (_fds, _waitfds, r)) + if want_token: + rfds.append(_tokenfds[0]) + assert rfds + assert state.is_flushed() + r,w,x = select.select(rfds, [], [], max_delay) + _debug('_tokenfds=%r; wfds=%r; readable: %r\n' % (_tokenfds, _waitfds, r)) for fd in r: - if _fds and fd == _fds[0]: + if fd == _tokenfds[0]: pass else: pd = _waitfds[fd] _debug("done: %r\n" % pd.name) - _release(1) + # redo subprocesses are expected to die without releasing their + # tokens, so things are less likely to get confused if they + # die abnormally. That means a token has 'disappeared' and we + # now need to recreate it. + b = _try_read(_cheatfds[0], 1) + _debug('GOT cheatfd\n') + if b == None: + _create_tokens(1) + if has_token(): + _release_except_mine() + else: + # someone exited with _cheats > 0, so we need to compensate + # by *not* re-creating a token now. + pass os.close(fd) del _waitfds[fd] rv = os.waitpid(pd.pid, 0) - assert(rv[0] == pd.pid) + assert rv[0] == pd.pid _debug("done1: rv=%r\n" % (rv,)) rv = rv[1] if os.WIFEXITED(rv): @@ -146,36 +293,59 @@ def wait(want_token): def has_token(): + assert _mytokens >= 0 if _mytokens >= 1: return True -def get_token(reason): - assert(state.is_flushed()) +def ensure_token(reason, max_delay=None): global _mytokens - assert(_mytokens <= 1) - setup(1) + assert state.is_flushed() + assert _mytokens <= 1 while 1: if _mytokens >= 1: _debug("_mytokens is %d\n" % _mytokens) - assert(_mytokens == 1) + assert _mytokens == 1 _debug('(%r) used my own token...\n' % reason) break - assert(_mytokens < 1) + assert _mytokens < 1 _debug('(%r) waiting for tokens...\n' % reason) - wait(want_token=1) + _wait(want_token=1, max_delay=max_delay) if _mytokens >= 1: break - assert(_mytokens < 1) - if _fds: - b = _try_read(_fds[0], 1) - if b == None: - raise Exception('unexpected EOF on token read') - if b: - _mytokens += 1 - _debug('(%r) got a token (%r).\n' % (reason, b)) + assert _mytokens < 1 + b = _try_read(_tokenfds[0], 1) + _debug('GOT tokenfd\n') + if b == '': + raise Exception('unexpected EOF on token read') + if b: + _mytokens += 1 + _debug('(%r) got a token (%r).\n' % (reason, b)) + break + if max_delay != None: + break + assert _mytokens <= 1 + + +def ensure_token_or_cheat(reason, cheatfunc): + global _mytokens, _cheats + backoff = 0.01 + while not has_token(): + while running() and not has_token(): + # If we already have a subproc running, then effectively we + # already have a token. Don't create a cheater token unless + # we're completely idle. + ensure_token(reason, max_delay=None) + ensure_token(reason, max_delay=min(1.0, backoff)) + backoff *= 2 + if not has_token(): + assert _mytokens == 0 + n = cheatfunc() + _debug('%s: %s: cheat = %d\n' % (vars.TARGET, reason, n)) + if n > 0: + _mytokens += n + _cheats += n break - assert(_mytokens <= 1) def running(): @@ -183,37 +353,50 @@ def running(): def wait_all(): - _debug("wait_all\n") - assert(state.is_flushed()) - while running(): + _debug("%d,%d -> wait_all\n" % (_mytokens, _cheats)) + assert state.is_flushed() + while 1: while _mytokens >= 1: release_mine() + if not running(): + break _debug("wait_all: wait()\n") - wait(want_token=0) + _wait(want_token=0, max_delay=None) _debug("wait_all: empty list\n") - get_token('self') # get my token back if _toplevel: - bb = '' - while 1: - b = _try_read(_fds[0], 8192) - bb += b - if not b: break - if len(bb) != _toplevel-1: - raise Exception('on exit: expected %d tokens; found %r' - % (_toplevel-1, len(bb))) - os.write(_fds[1], bb) + # If we're the toplevel and we're sure no child processes remain, + # then we know we're totally idle. Self-test to ensure no tokens + # mysteriously got created/destroyed. + tokens = _try_read_all(_tokenfds[0], 8192) + cheats = _try_read_all(_cheatfds[0], 8192) + _debug('toplevel: GOT %d tokens and %d cheats\n' + % (len(tokens), len(cheats))) + if len(tokens) - len(cheats) != _toplevel: + raise Exception('on exit: expected %d tokens; found %r-%r' + % (_toplevel, len(tokens), len(cheats))) + os.write(_tokenfds[1], tokens) + # note: when we return, we have *no* tokens, not even our own! + # If caller wants to continue, they have to obtain one right away. def force_return_tokens(): n = len(_waitfds) - if n: - _debug('%d tokens left in force_return_tokens\n' % n) - _debug('returning %d tokens\n' % n) + _debug('%d,%d -> %d jobs left in force_return_tokens\n' + % (_mytokens, _cheats, n)) for k in _waitfds.keys(): del _waitfds[k] - if _fds: - _release(n) - assert(state.is_flushed()) + _create_tokens(n) + if has_token(): + _release_except_mine() + assert _mytokens == 1, 'mytokens=%d' % _mytokens + assert _cheats <= _mytokens, 'mytokens=%d cheats=%d' % (_mytokens, _cheats) + assert _cheats in (0, 1), 'cheats=%d' % _cheats + if _cheats: + _debug('%d,%d -> force_return_tokens: recovering final token\n' + % (_mytokens, _cheats)) + _destroy_tokens(_cheats) + os.write(_cheatfds[1], 't' * _cheats) + assert state.is_flushed() def _pre_job(r, w, pfn): @@ -234,13 +417,13 @@ class Job: def start_job(reason, jobfunc, donefunc): - assert(state.is_flushed()) + assert state.is_flushed() global _mytokens - assert(_mytokens <= 1) - get_token(reason) - assert(_mytokens >= 1) - assert(_mytokens == 1) - _mytokens -= 1 + assert _mytokens <= 1 + assert _mytokens == 1 + # Subprocesses always start with 1 token, so we have to destroy ours + # in order for the universe to stay in balance. + _destroy_tokens(1) r,w = _make_pipe(50) pid = os.fork() if pid == 0: diff --git a/log.py b/log.py deleted file mode 100644 index 2acf000..0000000 --- a/log.py +++ /dev/null @@ -1,47 +0,0 @@ -import sys, os -import vars - -# By default, no output colouring. -RED = "" -GREEN = "" -YELLOW = "" -BOLD = "" -PLAIN = "" - -if sys.stderr.isatty() and (os.environ.get('TERM') or 'dumb') != 'dumb': - # ...use ANSI formatting codes. - RED = "\x1b[31m" - GREEN = "\x1b[32m" - YELLOW = "\x1b[33m" - BOLD = "\x1b[1m" - PLAIN = "\x1b[m" - - -def log_(s): - sys.stdout.flush() - if vars.DEBUG_PIDS: - sys.stderr.write('%d %s' % (os.getpid(), s)) - else: - sys.stderr.write(s) - sys.stderr.flush() - - -def log(s): - log_(''.join([GREEN, "redo ", vars.DEPTH, BOLD, s, PLAIN])) - -def err(s): - log_(''.join([RED, "redo ", vars.DEPTH, BOLD, s, PLAIN])) - -def warn(s): - log_(''.join([YELLOW, "redo ", vars.DEPTH, BOLD, s, PLAIN])) - - -def debug(s): - if vars.DEBUG >= 1: - log_('redo: %s%s' % (vars.DEPTH, s)) -def debug2(s): - if vars.DEBUG >= 2: - log_('redo: %s%s' % (vars.DEPTH, s)) -def debug3(s): - if vars.DEBUG >= 3: - log_('redo: %s%s' % (vars.DEPTH, s)) diff --git a/logs.py b/logs.py new file mode 100644 index 0000000..2ef1448 --- /dev/null +++ b/logs.py @@ -0,0 +1,149 @@ +import os, re, sys, time +import vars + + +def check_tty(file, color): + global RED, GREEN, YELLOW, BOLD, PLAIN + color_ok = file.isatty() and (os.environ.get('TERM') or 'dumb') != 'dumb' + if (color and color_ok) or color >= 2: + # ...use ANSI formatting codes. + RED = "\x1b[31m" + GREEN = "\x1b[32m" + YELLOW = "\x1b[33m" + BOLD = "\x1b[1m" + PLAIN = "\x1b[m" + else: + RED = "" + GREEN = "" + YELLOW = "" + BOLD = "" + PLAIN = "" + + +class RawLog(object): + def __init__(self, file): + self.file = file + + def write(self, s): + assert('\n' not in s) + sys.stdout.flush() + sys.stderr.flush() + self.file.write(s + '\n') + self.file.flush() + + +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): + if vars.DEBUG_PIDS: + redo = '%-6d redo ' % pid + else: + redo = 'redo ' + self.file.write(''.join([color, redo, vars.DEPTH, + BOLD if color else '', s, PLAIN, '\n'])) + + def write(self, s): + assert('\n' not in s) + sys.stdout.flush() + sys.stderr.flush() + g = REDO_RE.match(s) + if g: + all = g.group(0) + self.file.write(s[:-len(all)]) + words = g.group(1).split(':') + text = g.group(2) + kind, pid, when = words[0:3] + pid = int(pid) + if kind == 'unchanged': + self._pretty(pid, '', '%s (unchanged)' % text) + elif kind == 'check': + self._pretty(pid, GREEN, '(%s)' % text) + elif kind == 'do': + self._pretty(pid, GREEN, text) + elif kind == 'done': + rv, name = text.split(' ', 1) + rv = int(rv) + if rv: + self._pretty(pid, RED, '%s (exit %d)' % (name, rv)) + elif vars.VERBOSE or vars.XTRACE or vars.DEBUG: + self._pretty(pid, GREEN, '%s (done)' % name) + self.file.write('\n') + elif kind == 'locked': + if vars.DEBUG_LOCKS: + self._pretty(pid, GREEN, '%s (locked...)' % text) + elif kind == 'waiting': + if vars.DEBUG_LOCKS: + self._pretty(pid, GREEN, '%s (WAITING)' % text) + elif kind == 'unlocked': + if vars.DEBUG_LOCKS: + self._pretty(pid, GREEN, '%s (...unlocked!)' % text) + elif kind == 'error': + self.file.write(''.join([RED, 'redo: ', + BOLD, text, PLAIN, '\n'])) + elif kind == 'warning': + self.file.write(''.join([YELLOW, 'redo: ', + BOLD, text, PLAIN, '\n'])) + elif kind == 'debug': + self._pretty(pid, '', text) + else: + assert 0, 'Unexpected @@REDO kind: %r' % kind + else: + self.file.write(s + '\n') + self.file.flush() + + +_log = None + +def setup(file, pretty, color): + global _log + if pretty or vars.PRETTY: + check_tty(file, color=color) + _log = PrettyLog(file=file) + else: + _log = RawLog(file=file) + + +# FIXME: explicitly initialize in each program, for clarity +setup(file=sys.stderr, pretty=vars.PRETTY, color=vars.COLOR) + + +def write(s): + _log.write(s) + + +def meta(kind, s, pid=None): + assert(':' not in kind) + assert('@' not in kind) + assert('\n' not in s) + if pid == None: pid = os.getpid() + write('@@REDO:%s:%d:%.4f@@ %s' + % (kind, pid, time.time(), s)) + +def err(s): + s = s.rstrip() + meta('error', s) + +def warn(s): + s = s.rstrip() + meta('warning', s) + +def debug(s): + if vars.DEBUG >= 1: + s = s.rstrip() + meta('debug', s) + +def debug2(s): + if vars.DEBUG >= 2: + s = s.rstrip() + meta('debug', s) + +def debug3(s): + if vars.DEBUG >= 3: + s = s.rstrip() + meta('debug', s) diff --git a/mkdocs.yml b/mkdocs.yml index 889eeda..4ddc6e2 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -25,3 +25,4 @@ pages: - redo-targets: redo-targets.md - redo-ood: redo-ood.md - redo-whichdo: redo-whichdo.md + - redo-log: redo-log.md diff --git a/paths.py b/paths.py index abdfd91..c85580b 100644 --- a/paths.py +++ b/paths.py @@ -1,6 +1,6 @@ import os import vars -from log import err, debug2 +from logs import err, debug2 def _default_do_files(filename): diff --git a/redo-always.py b/redo-always.py index 3f2b569..2f2a60b 100755 --- a/redo-always.py +++ b/redo-always.py @@ -1,7 +1,7 @@ #!/usr/bin/env python2 import sys, os import vars, state -from log import err +from logs import err try: diff --git a/redo-ifchange.py b/redo-ifchange.py index af232be..aae4212 100755 --- a/redo-ifchange.py +++ b/redo-ifchange.py @@ -1,12 +1,12 @@ #!/usr/bin/env python2 -import sys, os +import sys, os, traceback import vars_init vars_init.init(sys.argv[1:]) import vars, state, builder, jwack, deps from helpers import unlink -from log import debug, debug2, err +from logs import debug, debug2, err def should_build(t): f = state.File(name=t) @@ -14,11 +14,14 @@ def should_build(t): raise builder.ImmediateReturn(32) dirty = deps.isdirty(f, depth = '', max_changed = vars.RUNID, already_checked=[]) - return dirty==[f] and deps.DIRTY or dirty + return f.is_generated, dirty==[f] and deps.DIRTY or dirty rv = 202 try: + if vars_init.is_toplevel: + builder.start_stdin_log_reader(status=True, details=True, + pretty=True, color=True, debug_locks=False, debug_pids=False) if vars.TARGET and not vars.UNLOCKED: me = os.path.join(vars.STARTDIR, os.path.join(vars.PWD, vars.TARGET)) @@ -27,6 +30,7 @@ try: else: f = me = None debug2('redo-ifchange: not adding depends.\n') + jwack.setup(1) try: targets = sys.argv[1:] if f: @@ -39,8 +43,17 @@ try: try: state.rollback() finally: - jwack.force_return_tokens() + try: + jwack.force_return_tokens() + except Exception, e: + traceback.print_exc(100, sys.stderr) + err('unexpected error: %r\n' % e) + rv = 1 except KeyboardInterrupt: + if vars_init.is_toplevel: + builder.await_log_reader() sys.exit(200) state.commit() +if vars_init.is_toplevel: + builder.await_log_reader() sys.exit(rv) diff --git a/redo-ifcreate.py b/redo-ifcreate.py index 297675b..16f6ddd 100755 --- a/redo-ifcreate.py +++ b/redo-ifcreate.py @@ -1,7 +1,7 @@ #!/usr/bin/env python2 import sys, os import vars, state -from log import err +from logs import err try: diff --git a/redo-log b/redo-log new file mode 120000 index 0000000..dd3b7c1 --- /dev/null +++ b/redo-log @@ -0,0 +1 @@ +redo-log.py \ No newline at end of file diff --git a/redo-log.py b/redo-log.py new file mode 100755 index 0000000..c29fbc8 --- /dev/null +++ b/redo-log.py @@ -0,0 +1,257 @@ +#!/usr/bin/env python +import errno, fcntl, os, re, struct, sys, termios, time +from atoi import atoi +import options + +optspec = """ +redo-log [options...] [targets...] +-- +r,recursive show build logs for dependencies too +u,unchanged show lines for dependencies not needing to be rebuilt +f,follow keep watching for more lines to be appended (like tail -f) +no-details only show 'redo' recursion trace, not build output +no-status don't display build summary line in --follow +no-pretty don't pretty-print logs, show raw @@REDO output instead +no-color disable ANSI color; --color to force enable (default: auto) +debug-locks print messages about file locking (useful for debugging) +debug-pids print process ids in log messages (useful for debugging) +ack-fd= (internal use only) print REDO-OK to this fd upon starting +""" +o = options.Options(optspec) +(opt, flags, extra) = o.parse(sys.argv[1:]) +targets = extra + +import vars_init +vars_init.init(list(targets)) + +import vars, logs, state + +topdir = os.getcwd() +already = set() +queue = [] +depth = [] +total_lines = 0 +status = None +start_time = time.time() + + +# regexp for matching "redo" lines in the log, which we use for recursion. +# format: +# redo path/to/target which might have spaces +# redo [unchanged] path/to/target which might have spaces +# redo path/to/target which might have spaces (comment) +REDO_LINE_RE = re.compile(r'^@@REDO:([^@]+)@@ (.*)\n$') + + +def _atoi(s): + try: + return int(s) + except TypeError: + return 0 + + +def _tty_width(): + s = struct.pack("HHHH", 0, 0, 0, 0) + try: + import fcntl, termios + s = fcntl.ioctl(sys.stderr.fileno(), termios.TIOCGWINSZ, s) + except (IOError, ImportError): + return _atoi(os.environ.get('WIDTH')) or 70 + (ysize,xsize,ypix,xpix) = struct.unpack('HHHH', s) + return xsize or 70 + + +def is_locked(fid): + return (fid is not None) and not state.Lock(fid=fid).trylock() + + +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: + return + if t != '-': + depth.append(t) + _fix_depth() + already.add(t) + mydir = os.path.dirname(t) + if t == '-': + f = sys.stdin + fid = None + loglock = None + logname = None + else: + try: + sf = state.File(name=t, allow_add=False) + except KeyError: + sys.stderr.write('redo-log: [%s] %r: not known to redo.\n' + % (os.getcwd(), t,)) + sys.exit(24) + fid = sf.id + del sf + state.rollback() + logname = state.logname(fid) + loglock = state.Lock(fid + state.LOG_LOCK_MAGIC) + loglock.waitlock(shared=True) + f = None + delay = 0.01 + was_locked = is_locked(fid) + line_head = '' + width = _tty_width() + while 1: + if not f: + try: + f = open(logname) + except IOError, e: + if e.errno == errno.ENOENT: + # ignore files without logs + pass + else: + raise + if f: + # Note: normally includes trailing \n. + # In 'follow' mode, might get a line with no trailing \n + # (eg. when ./configure is halfway through a test), which we + # deal with below. + line = f.readline() + else: + line = None + if not line and (not opt.follow or not was_locked): + # file not locked, and no new lines: done + break + if not line: + was_locked = is_locked(fid) + if opt.follow: + # Don't display status line for extremely short-lived runs + if opt.status and time.time() - start_time > 1.0: + width = _tty_width() + head = 'redo %s ' % ('{:,}'.format(total_lines)) + tail = '' + for n in reversed(depth): + remain = width - len(head) - len(tail) + # always leave room for a final '... ' prefix + if remain < len(n) + 4 + 1 or remain <= 4: + if len(n) < 6 or remain < 6 + 1 + 4: + tail = '... %s' % tail + else: + start = len(n) - (remain - 3 - 1) + tail = '...%s %s' % (n[start:], tail) + break + elif n != '-': + tail = n + ' ' + tail + status = head + tail + if len(status) > width: + sys.stderr.write('\nOVERSIZE STATUS (%d):\n%r\n' % + (len(status), status)) + assert(len(status) <= width) + sys.stdout.flush() + sys.stderr.write('\r%-*.*s\r' % (width, width, status)) + time.sleep(min(delay, 1.0)) + delay += 0.01 + continue + total_lines += 1 + delay = 0.01 + if not line.endswith('\n'): + line_head += line + continue + if line_head: + line = line_head + line + line_head = '' + if status: + sys.stdout.flush() + sys.stderr.write('\r%-*.*s\r' % (width, width, '')) + status = None + g = re.match(REDO_LINE_RE, line) + if g: + # FIXME: print prefix if @@REDO is not at start of line. + # logs.PrettyLog does it, but only if we actually call .write(). + 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.meta(kind, relname, pid=pid) + elif fixname not in already: + logs.meta('do', relname, pid=pid) + if opt.recursive: + if loglock: loglock.unlock() + 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 fixname not in already: + logs.meta('do', relname, pid=pid) + if opt.recursive: + assert text + if loglock: loglock.unlock() + 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: + if opt.details: + logs.write(line.rstrip()) + if loglock: + loglock.unlock() + if status: + sys.stdout.flush() + sys.stderr.write('\r%-*.*s\r' % (width, width, '')) + status = None + if line_head: + # partial line never got terminated + print line_head + if t != '-': + assert(depth[-1] == t) + depth.pop(-1) + _fix_depth() + +try: + if not targets: + sys.stderr.write('redo-log: give at least one target; maybe "all"?\n') + sys.exit(1) + if opt.status < 2 and not os.isatty(2): + opt.status = False + logs.setup(file=sys.stdout, pretty=opt.pretty, color=opt.color) + if opt.debug_locks: + vars.DEBUG_LOCKS = 1 + if opt.debug_pids: + vars.DEBUG_PIDS = 1 + if opt.ack_fd: + # Write back to owner, to let them know we started up okay and + # will be able to see their error output, so it's okay to close + # their old stderr. + ack_fd = int(opt.ack_fd) + assert(ack_fd > 2) + if os.write(ack_fd, 'REDO-OK\n') != 8: + raise Exception('write to ack_fd returned wrong length') + os.close(ack_fd) + queue += targets + while queue: + t = queue.pop(0) + if t != '-': + logs.meta('do', _rel(topdir, '.', t), pid=0) + catlog(t) +except KeyboardInterrupt: + sys.exit(200) +except IOError, e: + if e.errno == errno.EPIPE: + pass + else: + raise diff --git a/redo-ood.py b/redo-ood.py index 2264031..d1ef5ae 100755 --- a/redo-ood.py +++ b/redo-ood.py @@ -5,7 +5,7 @@ import vars_init vars_init.init([]) import vars, state, deps -from log import err +from logs import err if len(sys.argv[1:]) != 0: err('%s: no arguments expected.\n' % sys.argv[0]) diff --git a/redo-sources.py b/redo-sources.py index 6b89ece..579145d 100755 --- a/redo-sources.py +++ b/redo-sources.py @@ -5,7 +5,7 @@ import vars_init vars_init.init([]) import state -from log import err +from logs import err if len(sys.argv[1:]) != 0: err('%s: no arguments expected.\n' % sys.argv[0]) diff --git a/redo-stamp.py b/redo-stamp.py index 87989d6..a8f2dab 100755 --- a/redo-stamp.py +++ b/redo-stamp.py @@ -1,7 +1,7 @@ #!/usr/bin/env python2 import sys, os import vars, state -from log import err, debug2 +from logs import err, debug2 if len(sys.argv) > 1: err('%s: no arguments expected.\n' % sys.argv[0]) diff --git a/redo-targets.py b/redo-targets.py index ab953fb..cfed75d 100755 --- a/redo-targets.py +++ b/redo-targets.py @@ -5,7 +5,7 @@ import vars_init vars_init.init([]) import state -from log import err +from logs import err if len(sys.argv[1:]) != 0: err('%s: no arguments expected.\n' % sys.argv[0]) diff --git a/redo-unlocked.py b/redo-unlocked.py index bc49001..126f78a 100755 --- a/redo-unlocked.py +++ b/redo-unlocked.py @@ -1,7 +1,7 @@ #!/usr/bin/env python2 import sys, os import state -from log import err +from logs import err if len(sys.argv[1:]) < 2: err('%s: at least 2 arguments expected.\n' % sys.argv[0]) diff --git a/redo-whichdo.py b/redo-whichdo.py index 4495066..57a06eb 100755 --- a/redo-whichdo.py +++ b/redo-whichdo.py @@ -5,7 +5,7 @@ import vars_init vars_init.init_no_state() import paths -from log import err +from logs import err if len(sys.argv[1:]) != 1: err('%s: exactly one argument expected.\n' % sys.argv[0]) diff --git a/redo.py b/redo.py index 3324a4b..26fcb8c 100755 --- a/redo.py +++ b/redo.py @@ -1,5 +1,5 @@ #!/usr/bin/env python2 -import sys, os +import sys, os, traceback import options from helpers import atoi @@ -12,6 +12,11 @@ v,verbose print commands as they are read from .do files (variables intact) x,xtrace print commands as they are executed (variables expanded) k,keep-going keep going as long as possible even if some targets fail shuffle randomize the build order to find dependency bugs +no-details only show 'redo' recursion trace (to see more later, use redo-log) +no-status don't display build summary line at the bottom of the screen +no-log don't capture error output, just let it flow straight to stderr +no-pretty don't pretty-print logs, show raw @@REDO output instead +no-color disable ANSI color; --color to force enable (default: auto) debug-locks print messages about file locking (useful for debugging) debug-pids print process ids as part of log messages (useful for debugging) version print the current version and exit @@ -40,13 +45,27 @@ if opt.debug_locks: if opt.debug_pids: os.environ['REDO_DEBUG_PIDS'] = '1' +# This is slightly tricky: the log and pretty options default to true. We +# want to inherit that 'true' value from parent processes *unless* someone +# explicitly specifies the reverse. +if opt.no_log: + os.environ['REDO_LOG'] = '0' + if opt.no_pretty: + os.environ['REDO_PRETTY'] = '0' + if opt.no_color: + os.environ['REDO_COLOR'] = '0' + import vars_init vars_init.init(targets) import vars, state, builder, jwack -from log import warn, err +from logs import warn, err try: + if vars_init.is_toplevel: + builder.start_stdin_log_reader(status=opt.status, details=opt.details, + pretty=opt.pretty, color=opt.color, + debug_locks=opt.debug_locks, debug_pids=opt.debug_pids) for t in targets: if os.path.exists(t): f = state.File(name=t) @@ -61,13 +80,22 @@ try: jwack.setup(j) try: assert(state.is_flushed()) - retcode = builder.main(targets, lambda t: True) + retcode = builder.main(targets, lambda t: (True, True)) assert(state.is_flushed()) finally: try: state.rollback() finally: - jwack.force_return_tokens() + try: + jwack.force_return_tokens() + except Exception, e: + traceback.print_exc(100, sys.stderr) + err('unexpected error: %r\n' % e) + retcode = 1 + if vars_init.is_toplevel: + builder.await_log_reader() sys.exit(retcode) except KeyboardInterrupt: + if vars_init.is_toplevel: + builder.await_log_reader() sys.exit(200) diff --git a/state.py b/state.py index d27f472..9799748 100644 --- a/state.py +++ b/state.py @@ -1,7 +1,7 @@ import sys, os, errno, glob, stat, fcntl, sqlite3 import vars from helpers import unlink, close_on_exec, join -from log import warn, err, debug2, debug3 +from logs import warn, err, debug2, debug3 # When the module is imported, change the process title. # We do it here because this module is imported by all the scripts. @@ -21,6 +21,8 @@ ALWAYS='//ALWAYS' # an invalid filename that is always marked as dirty STAMP_DIR='dir' # the stamp of a directory; mtime is unhelpful STAMP_MISSING='0' # the stamp of a nonexistent file +LOG_LOCK_MAGIC=0x10000000 # fid offset for "log locks" + class CyclicDependencyError(Exception): pass @@ -163,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) @@ -174,7 +191,7 @@ class File(object): # use this mostly to avoid accidentally assigning to typos __slots__ = ['id'] + _file_cols[1:] - def _init_from_idname(self, id, name): + def _init_from_idname(self, id, name, allow_add): q = ('select %s from Files ' % join(', ', _file_cols)) if id != None: q += 'where rowid=?' @@ -189,7 +206,9 @@ class File(object): row = d.execute(q, l).fetchone() if not row: if not name: - raise Exception('No file with id=%r name=%r' % (id, name)) + raise KeyError('No file with id=%r name=%r' % (id, name)) + elif not allow_add: + raise KeyError('No file with name=%r' % (name,)) try: _write('insert into Files (name) values (?)', [name]) except sqlite3.IntegrityError: @@ -207,17 +226,17 @@ class File(object): if self.name == ALWAYS and self.changed_runid < vars.RUNID: self.changed_runid = vars.RUNID - def __init__(self, id=None, name=None, cols=None): + def __init__(self, id=None, name=None, cols=None, allow_add=True): if cols: return self._init_from_cols(cols) else: - return self._init_from_idname(id, name) + return self._init_from_idname(id, name, allow_add=allow_add) def __repr__(self): return "File(%r)" % (self.nicename(),) def refresh(self): - self._init_from_idname(self.id, None) + self._init_from_idname(self.id, None, allow_add=False) def save(self): cols = join(', ', ['%s=?'%i for i in _file_cols[2:]]) @@ -324,6 +343,11 @@ def files(): yield File(cols=cols) +def logname(fid): + """Given the id of a File, return the filename of its build log.""" + return os.path.join(vars.BASE, '.redo', 'log.%d' % fid) + + # FIXME: I really want to use fcntl F_SETLK, F_SETLKW, etc here. But python # doesn't do the lockdata structure in a portable way, so we have to use # fcntl.lockf() instead. Usually this is just a wrapper for fcntl, so it's @@ -365,10 +389,13 @@ class Lock: raise else: self.owned = True + return self.owned - def waitlock(self): + def waitlock(self, shared=False): self.check() - fcntl.lockf(self.lockfile, fcntl.LOCK_EX, 0, 0) + fcntl.lockf(self.lockfile, + fcntl.LOCK_SH if shared else fcntl.LOCK_EX, + 0, 0) self.owned = True def unlock(self): 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 diff --git a/vars.py b/vars.py index 25870fa..e28235a 100644 --- a/vars.py +++ b/vars.py @@ -16,6 +16,11 @@ DEBUG_PIDS = os.environ.get('REDO_DEBUG_PIDS', '') and 1 or 0 VERBOSE = os.environ.get('REDO_VERBOSE', '') and 1 or 0 XTRACE = os.environ.get('REDO_XTRACE', '') and 1 or 0 KEEP_GOING = os.environ.get('REDO_KEEP_GOING', '') and 1 or 0 +LOG = atoi(os.environ.get('REDO_LOG', '1')) # defaults on +LOG_INODE = os.environ.get('REDO_LOG_INODE', '') +COLOR = atoi(os.environ.get('REDO_COLOR', '1')) # defaults on +# subprocesses mustn't pretty-print if a parent is running redo-log +PRETTY = (not LOG) and atoi(os.environ.get('REDO_PRETTY', '1')) SHUFFLE = os.environ.get('REDO_SHUFFLE', '') and 1 or 0 STARTDIR = os.environ.get('REDO_STARTDIR', '') RUNID = atoi(os.environ.get('REDO_RUNID')) or None diff --git a/vars_init.py b/vars_init.py index 641c3a3..693a8dc 100644 --- a/vars_init.py +++ b/vars_init.py @@ -1,9 +1,13 @@ import sys, os +is_toplevel = False + + def init_no_state(): if not os.environ.get('REDO'): os.environ['REDO'] = 'NOT_DEFINED' + is_toplevel = True if not os.environ.get('REDO_BASE'): os.environ['REDO_BASE'] = 'NOT_DEFINED' @@ -11,6 +15,8 @@ def init_no_state(): def init(targets): if not os.environ.get('REDO'): # toplevel call to redo + global is_toplevel + is_toplevel = True if len(targets) == 0: targets.append('all') exenames = [os.path.abspath(sys.argv[0]), diff --git a/version/all.do b/version/all.do index db6567c..b774503 100644 --- a/version/all.do +++ b/version/all.do @@ -1,2 +1 @@ redo-ifchange vars _version.py -