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

@@ -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:
+                if is_target:
-                    log('[unchanged] %s\n' % _nice(self.t))
+                    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:
+        meta('done', '%d %s' % (rv, self.t))
-            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))
         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:
+            meta('locked', _nice(t))
-                log('%s (locked...)\n' % _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:
+                meta('waiting', _nice(t))
-                    warn('%s (WAITING)\n' % _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:
+            meta('unlocked', _nice(t))
-                log('%s (...unlocked!)\n' % _nice(t))
             if state.File(name=t).is_failed():
                 err('%s: failed in another thread\n' % _nice(t))
                 retcode[0] = 2

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

log.py

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

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)

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

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:

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)

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:

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.
+REDO_LINE_RE = re.compile(r'^@@REDO:([^@]+)@@ (.*)\n$')
-# 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 _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()
+            # FIXME: print prefix if @@REDO is not at start of line.
-            if attr == '[unchanged] ':
+            #   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:
+                    if text not in already:
-                        sys.stdout.write(line)
+                        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)
+                logs.write(line.rstrip())
-                if opt.recursive and (not comment or comment == ' (WAITING)'):
-                    assert name
-                    catlog(name)
         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)

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

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

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

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

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

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

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:

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.

version/all.do

@@ -1,2 +1 @@
 redo-ifchange vars _version.py
-