From 80aafaf29033499822263101d780b6e25d70566c Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Sat, 17 Nov 2018 10:21:11 -0500 Subject: [PATCH 01/13] Use signal.setitimer instead of signal.alarm. This gives us more precise timeouts, so that when _try_read hits a race condition, we don't suffer as badly. --- jwack.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/jwack.py b/jwack.py index 80786b4..a674e1a 100644 --- a/jwack.py +++ b/jwack.py @@ -59,7 +59,7 @@ def _try_read(fd, n): 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) except OSError, e: @@ -69,7 +69,7 @@ def _try_read(fd, n): 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 From b2411fe483c7c1b8bbe469e567b1c9f686f948c7 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Sat, 3 Nov 2018 22:09:18 -0400 Subject: [PATCH 02/13] redo-log: capture and linearize the output of redo builds. redo now saves the stderr from every .do script, for every target, into a file in the .redo directory. That means you can look up the logs from the most recent build of any target using the new redo-log command, for example: redo-log -r all The default is to show logs non-recursively, that is, it'll show when a target does redo-ifchange on another target, but it won't recurse into the logs for the latter target. With -r (recursive), it does. With -u (unchanged), it does even if redo-ifchange discovered that the target was already up-to-date; in that case, it prints the logs of the *most recent* time the target was generated. With --no-details, redo-log will show only the 'redo' lines, not the other log messages. For very noisy build systems (like recursing into a 'make' instance) this can be helpful to get an overview of what happened, without all the cruft. You can use the -f (follow) option like tail -f, to follow a build that's currently in progress until it finishes. redo itself spins up a copy of redo-log -r -f while it runs, so you can see what's going on. Still broken in this version: - No man page or new tests yet. - ANSI colors don't yet work (unless you use --raw-logs, which gives the old-style behaviour). - You can't redirect the output of a sub-redo to a file or a pipe right now, because redo-log is eating it. - The regex for matching 'redo' lines in the log is very gross. Instead, we should put the raw log files in a more machine-parseable format, and redo-log should turn that into human-readable format. - redo-log tries to "linearize" the logs, which makes them comprehensible even for a large parallel build. It recursively shows log messages for each target in depth-first tree order (by tracing into a new target every time it sees a 'redo' line). This works really well, but in some specific cases, the "topmost" redo instance can get stuck waiting for a jwack token, which makes it look like the whole build has stalled, when really redo-log is just waiting a long time for a particular subprocess to be able to continue. We'll need to add a specific workaround for that. --- builder.py | 80 +++++++++++++++++++++- jwack.py | 3 + log.py | 30 ++++---- redo-ifchange.py | 8 ++- redo-log | 1 + redo-log.py | 175 +++++++++++++++++++++++++++++++++++++++++++++++ redo.py | 16 ++++- state.py | 18 +++-- vars.py | 1 + vars_init.py | 6 ++ 10 files changed, 315 insertions(+), 23 deletions(-) create mode 120000 redo-log create mode 100755 redo-log.py diff --git a/builder.py b/builder.py index 4cc0fc8..b6ae049 100644 --- a/builder.py +++ b/builder.py @@ -1,7 +1,7 @@ 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 +from log import log, log_, debug, debug2, err, warn, check_tty def _nice(t): @@ -18,6 +18,72 @@ def _try_stat(filename): raise +log_reader_pid = None + + +def start_stdin_log_reader(status, details): + if vars.RAW_LOGS: 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() + else: + # child + try: + os.close(ar) + os.close(w) + os.dup2(r, 0) + os.close(r) + argv = [ + 'redo-log', + '--recursive', '--follow', + '--ack-fd', str(aw), + ('--status' if status else '--no-status'), + ('--details' if details else '--no-details'), + '-' + ] + 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 vars.RAW_LOGS: 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 +110,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 and vars.DEBUG_LOCKS: + log('[unchanged] %s\n' % _nice(self.t)) return self._after2(0) except ImmediateReturn, e: return self._after2(e.rv) @@ -117,6 +185,9 @@ class BuildJob: firstline = open(os.path.join(dodir, dofile)).readline().strip() if firstline.startswith('#!/'): argv[0:2] = firstline[2:].split(' ') + # make sure to create the logfile *before* writing the log about it. + # that way redo-log won't trace into an obsolete logfile. + if not vars.RAW_LOGS: open(state.logname(self.sf.id), 'w') log('%s\n' % _nice(t)) self.dodir = dodir self.basename = basename @@ -173,6 +244,11 @@ class BuildJob: os.dup2(self.f.fileno(), 1) os.close(self.f.fileno()) close_on_exec(1, False) + if not vars.RAW_LOGS: + logf = open(state.logname(self.sf.id), 'w') + os.dup2(logf.fileno(), 2) + close_on_exec(2, False) + logf.close() signal.signal(signal.SIGPIPE, signal.SIG_DFL) # python ignores SIGPIPE if vars.VERBOSE or vars.XTRACE: log_('* %s\n' % ' '.join(self.argv)) os.execvp(self.argv[0], self.argv) diff --git a/jwack.py b/jwack.py index a674e1a..949b756 100644 --- a/jwack.py +++ b/jwack.py @@ -37,6 +37,9 @@ 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), diff --git a/log.py b/log.py index 2acf000..0691e4b 100644 --- a/log.py +++ b/log.py @@ -1,20 +1,24 @@ 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 check_tty(): + global 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" + else: + RED = "" + GREEN = "" + YELLOW = "" + BOLD = "" + PLAIN = "" + +check_tty() def log_(s): diff --git a/redo-ifchange.py b/redo-ifchange.py index af232be..081d4e9 100755 --- a/redo-ifchange.py +++ b/redo-ifchange.py @@ -14,11 +14,13 @@ 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) if vars.TARGET and not vars.UNLOCKED: me = os.path.join(vars.STARTDIR, os.path.join(vars.PWD, vars.TARGET)) @@ -41,6 +43,10 @@ try: finally: jwack.force_return_tokens() 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-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..c7effa7 --- /dev/null +++ b/redo-log.py @@ -0,0 +1,175 @@ +#!/usr/bin/env python +import errno, os, re, sys, time +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-colorize don't colorize 'redo' log messages +no-status don't display build summary line in --follow +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, state + +already = set() +queue = [] +depth = [] +total_lines = 0 +status = None + + +# 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) +# FIXME: use a more structured format when writing the logs. +# That will prevent false positives and negatives. Then transform the +# structured format into a user-friendly format when printing in redo-log. +REDO_LINE_RE = re.compile(r'^redo\s+(\[\w+\] )?([^(:]+)( \([^)]+\))?\n$') + + +def is_locked(fid): + return (fid is not None) and not state.Lock(fid=fid).trylock() + + +def catlog(t): + global total_lines, status + if t in already: + return + depth.append(t) + already.add(t) + if t == '-': + f = sys.stdin + fid = None + logname = None + else: + try: + sf = state.File(name=t, allow_add=False) + except KeyError: + sys.stderr.write('redo-log: %r: not known to redo.\n' % (t,)) + sys.exit(24) + fid = sf.id + del sf + state.rollback() + logname = state.logname(fid) + f = None + delay = 0.01 + was_locked = is_locked(fid) + line_head = '' + 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: + if opt.status: + # FIXME use actual terminal width here + head = '[redo] %s ' % ('{:,}'.format(total_lines)) + tail = '' + for i in reversed(depth): + n = os.path.basename(i) + if 65 - len(head) - len(tail) < len(n) + 1: + tail = '... ' + tail + break + else: + tail = n + ' ' + tail + status = head + tail + sys.stdout.flush() + sys.stderr.write('\r%-70.70s\r' % 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%-70.70s\r' % '') + status = None + g = re.match(REDO_LINE_RE, line) + if g: + attr, name, comment = g.groups() + if attr == '[unchanged] ': + if opt.unchanged: + if name not in already: + sys.stdout.write(line) + if opt.recursive: + catlog(name) + else: + sys.stdout.write(line) + if opt.recursive and (not comment or comment == ' (WAITING)'): + assert name + catlog(name) + else: + if opt.details: + sys.stdout.write(line) + if status: + sys.stdout.flush() + sys.stderr.write('\r%-70.70s\r' % '') + status = None + if line_head: + # partial line never got terminated + print line_head + assert(depth[-1] == t) + depth.pop(-1) + +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 + if opt.ack_fd: + 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 != '-': + print 'redo %s' % t + catlog(t) +except KeyboardInterrupt: + sys.exit(200) +except IOError, e: + if e.errno == errno.EPIPE: + pass + else: + raise diff --git a/redo.py b/redo.py index 3324a4b..57c906c 100755 --- a/redo.py +++ b/redo.py @@ -12,6 +12,9 @@ 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 +raw-logs don't use redo-log, just send all output straight to stderr 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 @@ -35,7 +38,10 @@ if opt.keep_going: os.environ['REDO_KEEP_GOING'] = '1' if opt.shuffle: os.environ['REDO_SHUFFLE'] = '1' -if opt.debug_locks: +if opt.raw_logs: + os.environ['REDO_RAW_LOGS'] = '1' +if opt.debug_locks or not os.environ.get('REDO_RAW_LOGS'): + # FIXME: force-enabled for redo-log, for now os.environ['REDO_DEBUG_LOCKS'] = '1' if opt.debug_pids: os.environ['REDO_DEBUG_PIDS'] = '1' @@ -47,6 +53,8 @@ import vars, state, builder, jwack from log import warn, err try: + if vars_init.is_toplevel: + builder.start_stdin_log_reader(status=opt.status, details=opt.details) for t in targets: if os.path.exists(t): f = state.File(name=t) @@ -61,13 +69,17 @@ 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() + 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..ea34096 100644 --- a/state.py +++ b/state.py @@ -174,7 +174,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 +189,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 +209,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 +326,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,6 +372,7 @@ class Lock: raise else: self.owned = True + return self.owned def waitlock(self): self.check() diff --git a/vars.py b/vars.py index 25870fa..068c4c0 100644 --- a/vars.py +++ b/vars.py @@ -16,6 +16,7 @@ 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 +RAW_LOGS = os.environ.get('REDO_RAW_LOGS', '') and 1 or 0 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]), From e1f30c27657135ea8721c5e5dd60a54577301f7a Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Tue, 13 Nov 2018 02:51:23 -0500 Subject: [PATCH 03/13] redo-log: status line should use actual terminal width. This lets us pack more onto on line if the terminal is wider, and operate correctly if it's narrower. --- redo-log.py | 43 ++++++++++++++++++++++++++++++++----------- 1 file changed, 32 insertions(+), 11 deletions(-) diff --git a/redo-log.py b/redo-log.py index c7effa7..266106b 100755 --- a/redo-log.py +++ b/redo-log.py @@ -1,5 +1,5 @@ #!/usr/bin/env python -import errno, os, re, sys, time +import errno, fcntl, os, re, struct, sys, termios, time import options optspec = """ @@ -40,6 +40,17 @@ status = None REDO_LINE_RE = re.compile(r'^redo\s+(\[\w+\] )?([^(:]+)( \([^)]+\))?\n$') +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() @@ -68,6 +79,7 @@ def catlog(t): delay = 0.01 was_locked = is_locked(fid) line_head = '' + width = _tty_width() while 1: if not f: try: @@ -93,19 +105,28 @@ def catlog(t): was_locked = is_locked(fid) if opt.follow: if opt.status: - # FIXME use actual terminal width here - head = '[redo] %s ' % ('{:,}'.format(total_lines)) + width = _tty_width() + head = 'redo %s ' % ('{:,}'.format(total_lines)) tail = '' - for i in reversed(depth): - n = os.path.basename(i) - if 65 - len(head) - len(tail) < len(n) + 1: - tail = '... ' + 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 - else: + 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%-70.70s\r' % status) + sys.stderr.write('\r%-*.*s\r' % (width, width, status)) time.sleep(min(delay, 1.0)) delay += 0.01 continue @@ -119,7 +140,7 @@ def catlog(t): line_head = '' if status: sys.stdout.flush() - sys.stderr.write('\r%-70.70s\r' % '') + sys.stderr.write('\r%-*.*s\r' % (width, width, '')) status = None g = re.match(REDO_LINE_RE, line) if g: @@ -140,7 +161,7 @@ def catlog(t): sys.stdout.write(line) if status: sys.stdout.flush() - sys.stderr.write('\r%-70.70s\r' % '') + sys.stderr.write('\r%-*.*s\r' % (width, width, '')) status = None if line_head: # partial line never got terminated From 5c4f710f4e920973535f18d2b6ca9a9443d5f419 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Tue, 13 Nov 2018 04:05:42 -0500 Subject: [PATCH 04/13] Raw logs contain @@REDO lines instead of formatted data. This makes them more reliable to parse. redo-log can parse each line, format and print it, then recurse if necessary. This got a little ugly because I wanted 'redo --raw-logs' to work, which we want to format the output nicely, but not call redo-log. (As a result, --raw-logs has a different meaning to redo and redo-log, which is kinda dumb. I should fix that.) As an added bonus, redo-log now handles indenting of recursive logs, so if the build was a -> a/b -> a/b/c, and you look at the log for a/b, it can still start at the top level indentation. --- builder.py | 38 ++++++------ deps.py | 2 +- log.py | 51 ---------------- logs.py | 151 +++++++++++++++++++++++++++++++++++++++++++++++ paths.py | 2 +- redo-always.py | 2 +- redo-ifchange.py | 2 +- redo-ifcreate.py | 2 +- redo-log.py | 55 ++++++++++++----- redo-ood.py | 2 +- redo-sources.py | 2 +- redo-stamp.py | 2 +- redo-targets.py | 2 +- redo-unlocked.py | 2 +- redo-whichdo.py | 2 +- redo.py | 2 +- state.py | 2 +- version/all.do | 1 - 18 files changed, 221 insertions(+), 101 deletions(-) delete mode 100644 log.py create mode 100644 logs.py diff --git a/builder.py b/builder.py index b6ae049..b85b28f 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, check_tty +import logs +from logs import debug, debug2, err, warn, meta, check_tty def _nice(t): @@ -58,7 +59,7 @@ def start_stdin_log_reader(status, details): 'redo-log', '--recursive', '--follow', '--ack-fd', str(aw), - ('--status' if status else '--no-status'), + ('--status' if status and os.isatty(2) else '--no-status'), ('--details' if details else '--no-details'), '-' ] @@ -116,8 +117,8 @@ class BuildJob: raise ImmediateReturn(208) if not dirty: # target doesn't need to be built; skip the whole task - if is_target and vars.DEBUG_LOCKS: - log('[unchanged] %s\n' % _nice(self.t)) + if is_target: + meta('unchanged', _nice(self.t)) return self._after2(0) except ImmediateReturn, e: return self._after2(e.rv) @@ -162,7 +163,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) @@ -181,14 +182,14 @@ class BuildJob: ] if vars.VERBOSE: argv[1] += 'v' if vars.XTRACE: argv[1] += 'x' - if vars.VERBOSE or vars.XTRACE: log_('\n') + if vars.VERBOSE or vars.XTRACE: logs.write('\n') firstline = open(os.path.join(dodir, dofile)).readline().strip() if firstline.startswith('#!/'): argv[0:2] = firstline[2:].split(' ') # make sure to create the logfile *before* writing the log about it. # that way redo-log won't trace into an obsolete logfile. if not vars.RAW_LOGS: open(state.logname(self.sf.id), 'w') - log('%s\n' % _nice(t)) + meta('do', _nice(t)) self.dodir = dodir self.basename = basename self.ext = ext @@ -213,7 +214,7 @@ class BuildJob: # 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)) + meta('check', _nice(self.t)) state.commit() def run(): os.chdir(vars.BASE) @@ -250,8 +251,12 @@ class BuildJob: close_on_exec(2, False) logf.close() 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\n' % ' '.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 @@ -326,11 +331,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, self.t)) return rv def _after2(self, rv): @@ -382,8 +383,7 @@ def main(targets, shouldbuildfunc): else: lock.trylock() if not lock.owned: - if vars.DEBUG_LOCKS: - log('%s (locked...)\n' % _nice(t)) + meta('locked', _nice(t)) locked.append((f.id,t)) else: # We had to create f before we had a lock, because we need f.id @@ -427,8 +427,7 @@ 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)) + meta('waiting', _nice(t)) try: lock.check() except state.CyclicDependencyError: @@ -445,8 +444,7 @@ def main(targets, shouldbuildfunc): jwack.get_token(t) lock.trylock() assert(lock.owned) - if vars.DEBUG_LOCKS: - log('%s (...unlocked!)\n' % _nice(t)) + meta('unlocked', _nice(t)) if state.File(name=t).is_failed(): err('%s: failed in another thread\n' % _nice(t)) retcode[0] = 2 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/log.py b/log.py deleted file mode 100644 index 0691e4b..0000000 --- a/log.py +++ /dev/null @@ -1,51 +0,0 @@ -import sys, os -import vars - - -def check_tty(): - global 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" - else: - RED = "" - GREEN = "" - YELLOW = "" - BOLD = "" - PLAIN = "" - -check_tty() - - -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..2c093b6 --- /dev/null +++ b/logs.py @@ -0,0 +1,151 @@ +import os, re, sys, time +import vars + + +def check_tty(): + global 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" + 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.file = file + + def _pretty(self, pid, color, s): + if vars.DEBUG_PIDS: + redo = '%d 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: + # FIXME: support vars.DEBUG_PIDS somewhere + 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] + if kind == 'unchanged': + if vars.DEBUG >= 1: + 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): + global _log + if pretty: + check_tty() + _log = PrettyLog(file=file) + else: + _log = RawLog(file=file) + + +# FIXME: explicitly initialize in each program +setup(file=sys.stderr, pretty=False) + + +def write(s): + _log.write(s) + + +def meta(kind, s): + _log.meta(kind, s) + + +def meta(kind, s): + assert(':' not in kind) + assert('@' not in kind) + assert('\n' not in s) + write('@@REDO:%s:%d:%.4f@@ %s' + % (kind, os.getpid(), 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/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 081d4e9..72b84dd 100755 --- a/redo-ifchange.py +++ b/redo-ifchange.py @@ -6,7 +6,7 @@ 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) 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.py b/redo-log.py index 266106b..8aec98d 100755 --- a/redo-log.py +++ b/redo-log.py @@ -11,6 +11,7 @@ f,follow keep watching for more lines to be appended (like tail -f) no-details only show 'redo' recursion trace, not build output no-colorize don't colorize 'redo' log messages no-status don't display build summary line in --follow +raw-logs don't format logs, just send raw output straight to stdout ack-fd= (internal use only) print REDO-OK to this fd upon starting """ o = options.Options(optspec) @@ -20,7 +21,7 @@ targets = extra import vars_init vars_init.init(list(targets)) -import vars, state +import vars, logs, state already = set() queue = [] @@ -34,10 +35,14 @@ status = None # 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) -# FIXME: use a more structured format when writing the logs. -# That will prevent false positives and negatives. Then transform the -# structured format into a user-friendly format when printing in redo-log. -REDO_LINE_RE = re.compile(r'^redo\s+(\[\w+\] )?([^(:]+)( \([^)]+\))?\n$') +REDO_LINE_RE = re.compile(r'^@@REDO:([^@]+)@@ (.*)\n$') + + +def _atoi(s): + try: + return int(s) + except TypeError: + return 0 def _tty_width(): @@ -55,11 +60,16 @@ def is_locked(fid): return (fid is not None) and not state.Lock(fid=fid).trylock() +def _fix_depth(): + vars.DEPTH = (len(depth) - 1) * ' ' + + def catlog(t): global total_lines, status if t in already: return depth.append(t) + _fix_depth() already.add(t) if t == '-': f = sys.stdin @@ -144,21 +154,26 @@ def catlog(t): status = None g = re.match(REDO_LINE_RE, line) if g: - attr, name, comment = g.groups() - if attr == '[unchanged] ': + # 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] + if kind == 'unchanged': if opt.unchanged: - if name not in already: - sys.stdout.write(line) + if text not in already: + logs.write(line.rstrip()) if opt.recursive: - catlog(name) + catlog(text) + elif kind in ('do', 'waiting'): + logs.write(line.rstrip()) + if opt.recursive: + assert text + catlog(text) else: - sys.stdout.write(line) - if opt.recursive and (not comment or comment == ' (WAITING)'): - assert name - catlog(name) + logs.write(line.rstrip()) else: if opt.details: - sys.stdout.write(line) + logs.write(line.rstrip()) if status: sys.stdout.flush() sys.stderr.write('\r%-*.*s\r' % (width, width, '')) @@ -168,6 +183,7 @@ def catlog(t): print line_head assert(depth[-1] == t) depth.pop(-1) + _fix_depth() try: if not targets: @@ -175,7 +191,14 @@ try: sys.exit(1) if opt.status < 2 and not os.isatty(2): opt.status = False + if opt.raw_logs: + logs.setup(file=sys.stdout, pretty=False) + else: + logs.setup(file=sys.stdout, pretty=True) 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: @@ -185,7 +208,7 @@ try: while queue: t = queue.pop(0) if t != '-': - print 'redo %s' % t + logs.meta('do', t) catlog(t) except KeyboardInterrupt: sys.exit(200) 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 57c906c..4dc4780 100755 --- a/redo.py +++ b/redo.py @@ -50,7 +50,7 @@ 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: diff --git a/state.py b/state.py index ea34096..af484db 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. 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 - From e10bd1a9eb07abafbd5cfc0c8ad3cc291a0a6fdc Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Sat, 17 Nov 2018 01:39:10 -0500 Subject: [PATCH 05/13] redo-log: correctly indent first level of recursion. We don't want to print "-" at all, but that doesn't mean we should always omit indentation for the first level. --- redo-log.py | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/redo-log.py b/redo-log.py index 8aec98d..d5608ae 100755 --- a/redo-log.py +++ b/redo-log.py @@ -61,14 +61,15 @@ def is_locked(fid): def _fix_depth(): - vars.DEPTH = (len(depth) - 1) * ' ' + vars.DEPTH = len(depth) * ' ' def catlog(t): global total_lines, status if t in already: return - depth.append(t) + if t != '-': + depth.append(t) _fix_depth() already.add(t) if t == '-': @@ -181,8 +182,9 @@ def catlog(t): if line_head: # partial line never got terminated print line_head - assert(depth[-1] == t) - depth.pop(-1) + if t != '-': + assert(depth[-1] == t) + depth.pop(-1) _fix_depth() try: From 8b5a567b2e361975eceffa0c9d6eef1418e08a0f Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Sat, 17 Nov 2018 04:32:09 -0500 Subject: [PATCH 06/13] redo-log: prioritize the "foreground" process. When running a parallel build, redo-log -f (which is auto-started by redo) tries to traverse through the logs depth first, in the order parent processes started subprocesses. This works pretty well, but if its dependencies are locked, a process might have to give up its jobserver token while other stuff builds its dependencies. After the dependency finishes, the parent might not be able to get a token for quite some time, and the logs will appear to stop. To prevent this from happening, we can instantiate up to one "cheater" token, only in the foreground process (the one locked by redo-log -f), which will allow it to continue running, albeit a bit slowly (since it only has one token out of possibly many). When the process finishes, we then destroy the fake token. It gets a little complicated; see explanation at the top of jwack.py. --- builder.py | 42 +++++- jwack.py | 340 ++++++++++++++++++++++++++++++++++++----------- logs.py | 11 +- redo-ifchange.py | 13 +- redo-log.py | 26 +++- redo.py | 12 +- state.py | 8 +- 7 files changed, 348 insertions(+), 104 deletions(-) diff --git a/builder.py b/builder.py index b85b28f..3da03eb 100644 --- a/builder.py +++ b/builder.py @@ -22,7 +22,7 @@ def _try_stat(filename): log_reader_pid = None -def start_stdin_log_reader(status, details): +def start_stdin_log_reader(status, details, debug_locks, debug_pids): if vars.RAW_LOGS: return global log_reader_pid r, w = os.pipe() # main pipe to redo-log @@ -47,7 +47,7 @@ def start_stdin_log_reader(status, details): os.dup2(w, 1) os.dup2(w, 2) os.close(w) - check_tty() + check_tty(sys.stderr) else: # child try: @@ -61,6 +61,8 @@ def start_stdin_log_reader(status, details): '--ack-fd', str(aw), ('--status' if status and os.isatty(2) else '--no-status'), ('--details' if details else '--no-details'), + ('--debug-locks' if debug_locks else '--no-debug-locks'), + ('--debug-pids' if debug_pids else '--no-debug-pids'), '-' ] os.execvp(argv[0], argv) @@ -182,7 +184,6 @@ class BuildJob: ] if vars.VERBOSE: argv[1] += 'v' if vars.XTRACE: argv[1] += 'x' - if vars.VERBOSE or vars.XTRACE: logs.write('\n') firstline = open(os.path.join(dodir, dofile)).readline().strip() if firstline.startswith('#!/'): argv[0:2] = firstline[2:].split(' ') @@ -252,7 +253,7 @@ class BuildJob: logf.close() signal.signal(signal.SIGPIPE, signal.SIG_DFL) # python ignores SIGPIPE if vars.VERBOSE or vars.XTRACE: - logs.write('* %s\n' % ' '.join(self.argv).replace('\n', ' ')) + 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 @@ -353,6 +354,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. @@ -369,7 +391,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(): @@ -409,6 +431,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: @@ -427,6 +451,8 @@ def main(targets, shouldbuildfunc): import random time.sleep(random.random() * min(backoff, 1.0)) 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)) try: lock.check() @@ -436,12 +462,14 @@ 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) meta('unlocked', _nice(t)) diff --git a/jwack.py b/jwack.py index 949b756..1aaf432 100644 --- a/jwack.py +++ b/jwack.py @@ -1,36 +1,141 @@ # -# 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): @@ -50,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.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.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 @@ -106,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): @@ -149,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(): @@ -186,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): @@ -237,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/logs.py b/logs.py index 2c093b6..08071af 100644 --- a/logs.py +++ b/logs.py @@ -2,9 +2,9 @@ import os, re, sys, time import vars -def check_tty(): +def check_tty(file): global RED, GREEN, YELLOW, BOLD, PLAIN - if sys.stderr.isatty() and (os.environ.get('TERM') or 'dumb') != 'dumb': + if file.isatty() and (os.environ.get('TERM') or 'dumb') != 'dumb': # ...use ANSI formatting codes. RED = "\x1b[31m" GREEN = "\x1b[32m" @@ -52,15 +52,14 @@ class PrettyLog(object): sys.stderr.flush() g = REDO_RE.match(s) if g: - # FIXME: support vars.DEBUG_PIDS somewhere 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': - if vars.DEBUG >= 1: - self._pretty(pid, '', '%s (unchanged)' % text) + self._pretty(pid, '', '%s (unchanged)' % text) elif kind == 'check': self._pretty(pid, GREEN, '(%s)' % text) elif kind == 'do': @@ -102,7 +101,7 @@ _log = None def setup(file, pretty): global _log if pretty: - check_tty() + check_tty(file) _log = PrettyLog(file=file) else: _log = RawLog(file=file) diff --git a/redo-ifchange.py b/redo-ifchange.py index 72b84dd..86de027 100755 --- a/redo-ifchange.py +++ b/redo-ifchange.py @@ -1,5 +1,5 @@ #!/usr/bin/env python2 -import sys, os +import sys, os, traceback import vars_init vars_init.init(sys.argv[1:]) @@ -20,7 +20,8 @@ def should_build(t): rv = 202 try: if vars_init.is_toplevel: - builder.start_stdin_log_reader(status=True, details=True) + builder.start_stdin_log_reader(status=True, details=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)) @@ -29,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: @@ -41,7 +43,12 @@ 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() diff --git a/redo-log.py b/redo-log.py index d5608ae..159d6ca 100755 --- a/redo-log.py +++ b/redo-log.py @@ -12,6 +12,8 @@ no-details only show 'redo' recursion trace, not build output no-colorize don't colorize 'redo' log messages no-status don't display build summary line in --follow raw-logs don't format logs, just send raw output straight to stdout +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) @@ -75,6 +77,7 @@ def catlog(t): if t == '-': f = sys.stdin fid = None + loglock = None logname = None else: try: @@ -86,6 +89,8 @@ def catlog(t): 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) @@ -161,20 +166,31 @@ def catlog(t): kind, pid, when = words.split(':')[0:3] if kind == 'unchanged': if opt.unchanged: - if text not in already: + if opt.debug_locks: logs.write(line.rstrip()) + elif text not in already: + logs.meta('do', text) if opt.recursive: + if loglock: loglock.unlock() catlog(text) - elif kind in ('do', 'waiting'): - logs.write(line.rstrip()) + if loglock: loglock.waitlock(shared=True) + elif kind in ('do', 'waiting', 'locked', 'unlocked'): + if opt.debug_locks: + logs.write(line.rstrip()) + elif text not in already: + logs.meta('do', text) if opt.recursive: assert text + if loglock: loglock.unlock() catlog(text) + if loglock: loglock.waitlock(shared=True) 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, '')) @@ -197,6 +213,10 @@ try: logs.setup(file=sys.stdout, pretty=False) else: logs.setup(file=sys.stdout, pretty=True) + 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 diff --git a/redo.py b/redo.py index 4dc4780..cc6124a 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 @@ -54,7 +54,8 @@ from logs import warn, err try: if vars_init.is_toplevel: - builder.start_stdin_log_reader(status=opt.status, details=opt.details) + builder.start_stdin_log_reader(status=opt.status, details=opt.details, + debug_locks=opt.debug_locks, debug_pids=opt.debug_pids) for t in targets: if os.path.exists(t): f = state.File(name=t) @@ -75,7 +76,12 @@ 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) + retcode = 1 if vars_init.is_toplevel: builder.await_log_reader() sys.exit(retcode) diff --git a/state.py b/state.py index af484db..4556e68 100644 --- a/state.py +++ b/state.py @@ -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 @@ -374,9 +376,11 @@ class Lock: 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): From bc632982fc64beba98f7fed75a553b28e1b9caa6 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Mon, 19 Nov 2018 10:55:56 -0500 Subject: [PATCH 07/13] Split --raw-logs into --no-pretty and --no-log options. --no-log: don't capture logs or run redo-log (same as pre-redo-log redo) --no-pretty: don't pretty-print logs, print @@REDO lines. The latter is an option to both redo and redo-log. --- builder.py | 11 ++++++----- logs.py | 2 +- redo-ifchange.py | 2 +- redo-log.py | 7 ++----- redo.py | 17 ++++++++++++----- vars.py | 4 +++- 6 files changed, 25 insertions(+), 18 deletions(-) diff --git a/builder.py b/builder.py index 3da03eb..e4fcd09 100644 --- a/builder.py +++ b/builder.py @@ -22,8 +22,8 @@ def _try_stat(filename): log_reader_pid = None -def start_stdin_log_reader(status, details, debug_locks, debug_pids): - if vars.RAW_LOGS: return +def start_stdin_log_reader(status, details, pretty, 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 @@ -61,6 +61,7 @@ def start_stdin_log_reader(status, details, debug_locks, debug_pids): '--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'), '-' @@ -73,7 +74,7 @@ def start_stdin_log_reader(status, details, debug_locks, debug_pids): def await_log_reader(): - if vars.RAW_LOGS: return + if not vars.LOG: return global log_reader_pid if log_reader_pid > 0: # never actually close fd#1 or fd#2; insanity awaits. @@ -189,7 +190,7 @@ class BuildJob: argv[0:2] = firstline[2:].split(' ') # make sure to create the logfile *before* writing the log about it. # that way redo-log won't trace into an obsolete logfile. - if not vars.RAW_LOGS: open(state.logname(self.sf.id), 'w') + if vars.LOG: open(state.logname(self.sf.id), 'w') meta('do', _nice(t)) self.dodir = dodir self.basename = basename @@ -246,7 +247,7 @@ class BuildJob: os.dup2(self.f.fileno(), 1) os.close(self.f.fileno()) close_on_exec(1, False) - if not vars.RAW_LOGS: + if vars.LOG: logf = open(state.logname(self.sf.id), 'w') os.dup2(logf.fileno(), 2) close_on_exec(2, False) diff --git a/logs.py b/logs.py index 08071af..0397e9b 100644 --- a/logs.py +++ b/logs.py @@ -100,7 +100,7 @@ _log = None def setup(file, pretty): global _log - if pretty: + if pretty or vars.PRETTY: check_tty(file) _log = PrettyLog(file=file) else: diff --git a/redo-ifchange.py b/redo-ifchange.py index 86de027..8982fe6 100755 --- a/redo-ifchange.py +++ b/redo-ifchange.py @@ -21,7 +21,7 @@ rv = 202 try: if vars_init.is_toplevel: builder.start_stdin_log_reader(status=True, details=True, - debug_locks=False, debug_pids=False) + pretty=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)) diff --git a/redo-log.py b/redo-log.py index 159d6ca..ae2d86c 100755 --- a/redo-log.py +++ b/redo-log.py @@ -11,7 +11,7 @@ f,follow keep watching for more lines to be appended (like tail -f) no-details only show 'redo' recursion trace, not build output no-colorize don't colorize 'redo' log messages no-status don't display build summary line in --follow -raw-logs don't format logs, just send raw output straight to stdout +no-pretty don't pretty-print logs, show raw @@REDO output instead 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 @@ -209,10 +209,7 @@ try: sys.exit(1) if opt.status < 2 and not os.isatty(2): opt.status = False - if opt.raw_logs: - logs.setup(file=sys.stdout, pretty=False) - else: - logs.setup(file=sys.stdout, pretty=True) + logs.setup(file=sys.stdout, pretty=opt.pretty) if opt.debug_locks: vars.DEBUG_LOCKS = 1 if opt.debug_pids: diff --git a/redo.py b/redo.py index cc6124a..b4e4fc6 100755 --- a/redo.py +++ b/redo.py @@ -14,7 +14,8 @@ 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 -raw-logs don't use redo-log, just send all output straight to stderr +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 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 @@ -38,14 +39,19 @@ if opt.keep_going: os.environ['REDO_KEEP_GOING'] = '1' if opt.shuffle: os.environ['REDO_SHUFFLE'] = '1' -if opt.raw_logs: - os.environ['REDO_RAW_LOGS'] = '1' -if opt.debug_locks or not os.environ.get('REDO_RAW_LOGS'): - # FIXME: force-enabled for redo-log, for now +if opt.debug_locks: os.environ['REDO_DEBUG_LOCKS'] = '1' 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' + import vars_init vars_init.init(targets) @@ -55,6 +61,7 @@ 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, debug_locks=opt.debug_locks, debug_pids=opt.debug_pids) for t in targets: if os.path.exists(t): diff --git a/vars.py b/vars.py index 068c4c0..d2bda0b 100644 --- a/vars.py +++ b/vars.py @@ -16,7 +16,9 @@ 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 -RAW_LOGS = os.environ.get('REDO_RAW_LOGS', '') and 1 or 0 +LOG = atoi(os.environ.get('REDO_LOG', '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 From f49d311471c0e379e7f1c09fe4133b0835a7795c Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Mon, 19 Nov 2018 11:00:47 -0500 Subject: [PATCH 08/13] redo-log: --debug-pids works properly again. Pretty-printing from redo-log was accidentally using the redo-log pid instead of the pid parsed from the raw logs. --- logs.py | 11 ++++------- redo-log.py | 8 +++++--- 2 files changed, 9 insertions(+), 10 deletions(-) diff --git a/logs.py b/logs.py index 0397e9b..9073ba8 100644 --- a/logs.py +++ b/logs.py @@ -40,7 +40,7 @@ class PrettyLog(object): def _pretty(self, pid, color, s): if vars.DEBUG_PIDS: - redo = '%d redo ' % pid + redo = '%-6d redo ' % pid else: redo = 'redo ' self.file.write(''.join([color, redo, vars.DEPTH, @@ -115,16 +115,13 @@ def write(s): _log.write(s) -def meta(kind, s): - _log.meta(kind, s) - - -def meta(kind, 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, os.getpid(), time.time(), s)) + % (kind, pid, time.time(), s)) def err(s): s = s.rstrip() diff --git a/redo-log.py b/redo-log.py index ae2d86c..7bfa85d 100755 --- a/redo-log.py +++ b/redo-log.py @@ -1,5 +1,6 @@ #!/usr/bin/env python import errno, fcntl, os, re, struct, sys, termios, time +from atoi import atoi import options optspec = """ @@ -164,12 +165,13 @@ def catlog(t): # 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) if kind == 'unchanged': if opt.unchanged: if opt.debug_locks: logs.write(line.rstrip()) elif text not in already: - logs.meta('do', text) + logs.meta('do', text, pid=pid) if opt.recursive: if loglock: loglock.unlock() catlog(text) @@ -178,7 +180,7 @@ def catlog(t): if opt.debug_locks: logs.write(line.rstrip()) elif text not in already: - logs.meta('do', text) + logs.meta('do', text, pid=pid) if opt.recursive: assert text if loglock: loglock.unlock() @@ -227,7 +229,7 @@ try: while queue: t = queue.pop(0) if t != '-': - logs.meta('do', t) + logs.meta('do', t, pid=0) catlog(t) except KeyboardInterrupt: sys.exit(200) From d82326a39d70d7fe897dabd6bb85fa746905e1f4 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Mon, 19 Nov 2018 11:22:53 -0500 Subject: [PATCH 09/13] Add --color and --no-color options. By default, we auto-detect color mode (if it's a tty, color default on, else off). But you can force it either way. --- builder.py | 9 ++++++--- logs.py | 13 +++++++------ redo-ifchange.py | 2 +- redo-log.py | 4 ++-- redo.py | 5 ++++- vars.py | 1 + 6 files changed, 21 insertions(+), 13 deletions(-) diff --git a/builder.py b/builder.py index e4fcd09..aff26c7 100644 --- a/builder.py +++ b/builder.py @@ -22,7 +22,8 @@ def _try_stat(filename): log_reader_pid = None -def start_stdin_log_reader(status, details, pretty, debug_locks, debug_pids): +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 @@ -47,7 +48,7 @@ def start_stdin_log_reader(status, details, pretty, debug_locks, debug_pids): os.dup2(w, 1) os.dup2(w, 2) os.close(w) - check_tty(sys.stderr) + check_tty(sys.stderr, vars.COLOR) else: # child try: @@ -64,8 +65,10 @@ def start_stdin_log_reader(status, details, pretty, debug_locks, debug_pids): ('--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) diff --git a/logs.py b/logs.py index 9073ba8..54a17ee 100644 --- a/logs.py +++ b/logs.py @@ -2,9 +2,10 @@ import os, re, sys, time import vars -def check_tty(file): +def check_tty(file, color): global RED, GREEN, YELLOW, BOLD, PLAIN - if file.isatty() and (os.environ.get('TERM') or 'dumb') != 'dumb': + 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" @@ -98,17 +99,17 @@ class PrettyLog(object): _log = None -def setup(file, pretty): +def setup(file, pretty, color): global _log if pretty or vars.PRETTY: - check_tty(file) + check_tty(file, color=color) _log = PrettyLog(file=file) else: _log = RawLog(file=file) -# FIXME: explicitly initialize in each program -setup(file=sys.stderr, pretty=False) +# FIXME: explicitly initialize in each program, for clarity +setup(file=sys.stderr, pretty=vars.PRETTY, color=vars.COLOR) def write(s): diff --git a/redo-ifchange.py b/redo-ifchange.py index 8982fe6..aae4212 100755 --- a/redo-ifchange.py +++ b/redo-ifchange.py @@ -21,7 +21,7 @@ rv = 202 try: if vars_init.is_toplevel: builder.start_stdin_log_reader(status=True, details=True, - pretty=True, debug_locks=False, debug_pids=False) + 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)) diff --git a/redo-log.py b/redo-log.py index 7bfa85d..63f5503 100755 --- a/redo-log.py +++ b/redo-log.py @@ -10,9 +10,9 @@ 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-colorize don't colorize 'redo' log messages 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 @@ -211,7 +211,7 @@ try: sys.exit(1) if opt.status < 2 and not os.isatty(2): opt.status = False - logs.setup(file=sys.stdout, pretty=opt.pretty) + logs.setup(file=sys.stdout, pretty=opt.pretty, color=opt.color) if opt.debug_locks: vars.DEBUG_LOCKS = 1 if opt.debug_pids: diff --git a/redo.py b/redo.py index b4e4fc6..26fcb8c 100755 --- a/redo.py +++ b/redo.py @@ -16,6 +16,7 @@ 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 @@ -51,6 +52,8 @@ 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) @@ -61,7 +64,7 @@ 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, + 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): diff --git a/vars.py b/vars.py index d2bda0b..3b95915 100644 --- a/vars.py +++ b/vars.py @@ -17,6 +17,7 @@ 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 +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 From 048df77aa68419a17aeda5330eafa09f9dbdea98 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Mon, 19 Nov 2018 15:42:05 -0500 Subject: [PATCH 10/13] redo-log: don't show status line until >1.0 seconds after starting. For very short builds, it looks nicer to not flicker the status line for a split second. --- redo-log.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/redo-log.py b/redo-log.py index 63f5503..1026175 100755 --- a/redo-log.py +++ b/redo-log.py @@ -31,6 +31,7 @@ queue = [] depth = [] total_lines = 0 status = None +start_time = time.time() # regexp for matching "redo" lines in the log, which we use for recursion. @@ -121,7 +122,8 @@ def catlog(t): if not line: was_locked = is_locked(fid) if opt.follow: - if opt.status: + # 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 = '' From 7165b342f545bd4090db438ea3b76f41897f34b7 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Mon, 19 Nov 2018 16:27:41 -0500 Subject: [PATCH 11/13] redo-log: fix stdout vs stderr; don't recapture if .do script redirects stderr. redo-log should log to stdout, because when you ask for the specific logs from a run, the logs are the output you requested. redo-log's stderr should be about any errors retrieving that output. On the other hand, when you run redo, the logs are literally the stderr of the build steps, which are incidental to the main job (building things). So that should be send to stderr. Previously, we were sending to stderr when --no-log, but stdout when --log, which is totally wrong. Also, adding redo-log had the unexpected result that if a .do script redirected the stderr of a sub-redo or redo-ifchange to a file or pipe, the output would be eaten by redo-log instead of the intended output. So a test runner like this: self.test: redo self.runtest 2>&1 | grep ERROR would not work; the self.runtest output would be sent to redo's log buffer (and from there, probably printed to the toplevel redo's stderr) rather than passed along to grep. --- builder.py | 26 ++++++++++++++++++++++---- vars.py | 1 + 2 files changed, 23 insertions(+), 4 deletions(-) diff --git a/builder.py b/builder.py index aff26c7..490f196 100644 --- a/builder.py +++ b/builder.py @@ -56,6 +56,12 @@ def start_stdin_log_reader(status, details, pretty, color, 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', @@ -251,10 +257,22 @@ class BuildJob: os.close(self.f.fileno()) close_on_exec(1, False) if vars.LOG: - logf = open(state.logname(self.sf.id), 'w') - os.dup2(logf.fileno(), 2) - close_on_exec(2, False) - logf.close() + 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_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'] signal.signal(signal.SIGPIPE, signal.SIG_DFL) # python ignores SIGPIPE if vars.VERBOSE or vars.XTRACE: logs.write('* %s' % ' '.join(self.argv).replace('\n', ' ')) diff --git a/vars.py b/vars.py index 3b95915..e28235a 100644 --- a/vars.py +++ b/vars.py @@ -17,6 +17,7 @@ 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')) From 4edb6f78e0ada57c98bb14fcca67d77ff81e64b0 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Mon, 19 Nov 2018 17:09:40 -0500 Subject: [PATCH 12/13] 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 From 6ad0b032d4825b5badd9e0eedcd205cbb9069bcb Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Mon, 19 Nov 2018 19:28:25 -0500 Subject: [PATCH 13/13] redo-log: add man page. --- Documentation/redo-log.md | 83 +++++++++++++++++++++++++++++++++++++++ Documentation/redo.md | 29 ++++++++++++++ clean.do | 2 +- mkdocs.yml | 1 + 4 files changed, 114 insertions(+), 1 deletion(-) create mode 100644 Documentation/redo-log.md 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/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/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