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 -