Introduce BUP_DEBUG, --debug, and tone down the log messages a lot.

There's a new global bup option, --debug (-D) that increments BUP_DEBUG.  If
BUP_DEBUG >=1, debug1() prints; if >= 2, debug2() prints.

We change a bunch of formerly-always-printing log() messages to debug1 or
debug2, so now a typical bup session should be a lot less noisy.

This affects midx in particular, which was *way* too noisy now that 'bup
save' and 'bup server' were running it automatically every now and then.

Signed-off-by: Avery Pennarun <apenwarr@gmail.com>

cmd/midx-cmd.py

@@ -12,6 +12,7 @@
 o,output=  output midx filename (default: auto-generated)
 a,auto     automatically create .midx from any unindexed .idx files
 f,force    automatically create .midx from *all* .idx files
+p,print    print names of generated midx files
 max-files= maximum number of idx files to open at once [-1]
 dir=       directory containing idx/midx files
 """
@@ -32,14 +33,14 @@ def max_files():
 
 def merge(idxlist, bits, table):
     count = 0
-    for e in git.idxmerge(idxlist):
+    for e in git.idxmerge(idxlist, final_progress=False):
         count += 1
         prefix = git.extract_bits(e, bits)
         table[prefix] = count
         yield e
 
 
-def _do_midx(outdir, outfilename, infilenames):
+def _do_midx(outdir, outfilename, infilenames, prefixstr):
     if not outfilename:
         assert(outdir)
         sum = Sha1('\0'.join(infilenames)).hexdigest()
@@ -55,17 +56,18 @@ def _do_midx(outdir, outfilename, infilenames):
         inp.append(ix)
         total += len(ix)
 
-    log('Merging %d indexes (%d objects).\n' % (len(infilenames), total))
+    log('midx: %smerging %d indexes (%d objects).\n'
+        % (prefixstr, len(infilenames), total))
     if (not opt.force and (total < 1024 and len(infilenames) < 3)) \
        or len(infilenames) < 2 \
        or (opt.force and not total):
-        log('midx: nothing to do.\n')
+        debug1('midx: nothing to do.\n')
         return
 
     pages = int(total/SHA_PER_PAGE) or 1
     bits = int(math.ceil(math.log(pages, 2)))
     entries = 2**bits
-    log('Table size: %d (%d bits)\n' % (entries*4, bits))
+    debug1('midx: table size: %d (%d bits)\n' % (entries*4, bits))
 
     table = [0]*entries
 
@@ -103,9 +105,9 @@ def _do_midx(outdir, outfilename, infilenames):
     return total,outfilename
 
 
-def do_midx(outdir, outfilename, infilenames):
-    rv = _do_midx(outdir, outfilename, infilenames)
-    if rv:
+def do_midx(outdir, outfilename, infilenames, prefixstr):
+    rv = _do_midx(outdir, outfilename, infilenames, prefixstr)
+    if rv and opt['print']:
         print rv[1]
 
 
@@ -133,7 +135,7 @@ def do_midx_dir(path):
                     already[iname] = 1
                     any = 1
             if not any:
-                log('%r is redundant\n' % mname)
+                debug1('%r is redundant\n' % mname)
                 unlink(mname)
                 already[mname] = 1
 
@@ -150,30 +152,37 @@ def do_midx_dir(path):
     DESIRED_HWM = opt.force and 1 or 5
     DESIRED_LWM = opt.force and 1 or 2
     existed = dict((name,1) for sz,name in all)
-    log('midx: %d indexes; want no more than %d.\n' % (len(all), DESIRED_HWM))
+    debug1('midx: %d indexes; want no more than %d.\n' 
+           % (len(all), DESIRED_HWM))
     if len(all) <= DESIRED_HWM:
-        log('midx: nothing to do.\n')
+        debug1('midx: nothing to do.\n')
     while len(all) > DESIRED_HWM:
         all.sort()
         part1 = [name for sz,name in all[:len(all)-DESIRED_LWM+1]]
         part2 = all[len(all)-DESIRED_LWM+1:]
         all = list(do_midx_group(path, part1)) + part2
         if len(all) > DESIRED_HWM:
-            log('\nStill too many indexes (%d > %d).  Merging again.\n'
-                % (len(all), DESIRED_HWM))
+            debug1('\nStill too many indexes (%d > %d).  Merging again.\n'
+                   % (len(all), DESIRED_HWM))
 
-    for sz,name in all:
-        if not existed.get(name):
-            print name
+    if opt['print']:
+        for sz,name in all:
+            if not existed.get(name):
+                print name
 
 
 def do_midx_group(outdir, infiles):
-    for sublist in _group(infiles, opt.max_files):
-        rv = _do_midx(path, None, sublist)
+    groups = list(_group(infiles, opt.max_files))
+    gprefix = ''
+    for n,sublist in enumerate(groups):
+        if len(groups) != 1:
+            gprefix = 'Group %d: ' % (n+1)
+        rv = _do_midx(path, None, sublist, gprefix)
         if rv:
             yield rv
 
 
+handle_ctrl_c()
 
 o = options.Options('bup midx', optspec)
 (opt, flags, extra) = o.parse(sys.argv[1:])
@@ -188,16 +197,16 @@ def do_midx_group(outdir, infiles):
 assert(opt.max_files >= 5)
 
 if extra:
-    do_midx(git.repo('objects/pack'), opt.output, extra)
+    do_midx(git.repo('objects/pack'), opt.output, extra, '')
 elif opt.auto or opt.force:
     if opt.dir:
         paths = [opt.dir]
     else:
         paths = [git.repo('objects/pack')]
         paths += glob.glob(git.repo('index-cache/*/.'))
     for path in paths:
-        log('midx: scanning %s\n' % path)
+        debug1('midx: scanning %s\n' % path)
         do_midx_dir(path)
-        log('\n')
+        debug1('\n')
 else:
     o.fatal("you must use -f or -a or provide input filenames")

cmd/server-cmd.py

@@ -8,13 +8,13 @@
 
 def init_dir(conn, arg):
     git.init_repo(arg)
-    log('bup server: bupdir initialized: %r\n' % git.repodir)
+    debug1('bup server: bupdir initialized: %r\n' % git.repodir)
     conn.ok()
 
 
 def set_dir(conn, arg):
     git.check_repo_or_die(arg)
-    log('bup server: bupdir is %r\n' % git.repodir)
+    debug1('bup server: bupdir is %r\n' % git.repodir)
     conn.ok()
 
 
@@ -51,9 +51,9 @@ def receive_objects(conn, junk):
             w.abort()
             raise Exception('object read: expected length header, got EOF\n')
         n = struct.unpack('!I', ns)[0]
-        #log('expecting %d bytes\n' % n)
+        #debug2('expecting %d bytes\n' % n)
         if not n:
-            log('bup server: received %d object%s.\n' 
+            debug1('bup server: received %d object%s.\n' 
                 % (w.count, w.count!=1 and "s" or ''))
             fullpath = w.close()
             if fullpath:
@@ -62,13 +62,13 @@ def receive_objects(conn, junk):
             conn.ok()
             return
         elif n == 0xffffffff:
-            log('bup server: receive-objects suspended.\n')
+            debug2('bup server: receive-objects suspended.\n')
             suspended_w = w
             conn.ok()
             return
 
         buf = conn.read(n)  # object sizes in bup are reasonably small
-        #log('read %d bytes\n' % n)
+        #debug2('read %d bytes\n' % n)
         if len(buf) < n:
             w.abort()
             raise Exception('object read: expected %d bytes, got %d\n'
@@ -90,7 +90,7 @@ def receive_objects(conn, junk):
             # efficient.
             w.objcache.refresh(skip_midx = True)
             oldpack = w.objcache.exists(sha)
-            log('new suggestion: %r\n' % oldpack)
+            debug2('new suggestion: %r\n' % oldpack)
             assert(oldpack)
             assert(oldpack != True)
             assert(not oldpack.endswith('.midx'))
@@ -99,7 +99,7 @@ def receive_objects(conn, junk):
             assert(oldpack.endswith('.idx'))
             (dir,name) = os.path.split(oldpack)
             if not (name in suggested):
-                log("bup server: suggesting index %s\n" % name)
+                debug1("bup server: suggesting index %s\n" % name)
                 conn.write('index %s\n' % name)
                 suggested[name] = 1
         else:
@@ -150,7 +150,7 @@ def cat(conn, id):
 if extra:
     o.fatal('no arguments expected')
 
-log('bup server: reading from stdin.\n')
+debug2('bup server: reading from stdin.\n')
 
 commands = {
     'init-dir': init_dir,
@@ -171,7 +171,7 @@ def cat(conn, id):
     line = _line.strip()
     if not line:
         continue
-    log('bup server: command: %r\n' % line)
+    debug1('bup server: command: %r\n' % line)
     words = line.split(' ', 1)
     cmd = words[0]
     rest = len(words)>1 and words[1] or ''
@@ -184,4 +184,4 @@ def cat(conn, id):
         else:
             raise Exception('unknown server command: %r\n' % line)
 
-log('bup server: done\n')
+debug1('bup server: done\n')

lib/bup/client.py

@@ -134,11 +134,11 @@ def sync_indexes_del(self):
         mkdirp(self.cachedir)
         for f in os.listdir(self.cachedir):
             if f.endswith('.idx') and not f in all:
-                log('pruning old index: %r\n' % f)
+                debug1('client: pruning old index: %r\n' % f)
                 os.unlink(os.path.join(self.cachedir, f))
 
     def sync_index(self, name):
-        #log('requesting %r\n' % name)
+        #debug1('requesting %r\n' % name)
         self.check_busy()
         mkdirp(self.cachedir)
         self.conn.write('send-index %s\n' % name)
@@ -147,12 +147,12 @@ def sync_index(self, name):
         fn = os.path.join(self.cachedir, name)
         f = open(fn + '.tmp', 'w')
         count = 0
-        progress('Receiving index: %d/%d\r' % (count, n))
+        progress('Receiving index from server: %d/%d\r' % (count, n))
         for b in chunkyreader(self.conn, n):
             f.write(b)
             count += len(b)
-            progress('Receiving index: %d/%d\r' % (count, n))
-        progress('Receiving index: %d/%d, done.\n' % (count, n))
+            progress('Receiving index from server: %d/%d\r' % (count, n))
+        progress('Receiving index from server: %d/%d, done.\n' % (count, n))
         self.check_ok()
         f.close()
         os.rename(fn + '.tmp', fn)
@@ -166,7 +166,7 @@ def _make_objcache(self):
         return git.PackIdxList(self.cachedir)
 
     def _suggest_pack(self, indexname):
-        log('received index suggestion: %s\n' % indexname)
+        debug1('client: received index suggestion: %s\n' % indexname)
         ob = self._busy
         if ob:
             assert(ob == 'receive-objects')

lib/bup/git.py

@@ -383,16 +383,16 @@ def refresh(self, skip_midx = False):
                             any += 1
                             break
                     if not any and not ix.force_keep:
-                        log('midx: removing redundant: %s\n'
-                            % os.path.basename(ix.name))
+                        debug1('midx: removing redundant: %s\n'
+                               % os.path.basename(ix.name))
                         unlink(ix.name)
             for f in os.listdir(self.dir):
                 full = os.path.join(self.dir, f)
                 if f.endswith('.idx') and not d.get(full):
                     ix = PackIdx(full)
                     d[full] = ix
             self.packs = list(set(d.values()))
-        log('PackIdxList: using %d index%s.\n'
+        debug1('PackIdxList: using %d index%s.\n'
             % (len(self.packs), len(self.packs)!=1 and 'es' or ''))
 
     def add(self, hash):
@@ -429,7 +429,7 @@ def open_idx(filename):
         raise GitError('idx filenames must end with .idx or .midx')
 
 
-def idxmerge(idxlist):
+def idxmerge(idxlist, final_progress=True):
     """Generate a list of all the objects reachable in a PackIdxList."""
     total = sum(len(i) for i in idxlist)
     iters = (iter(i) for i in idxlist)
@@ -451,7 +451,8 @@ def idxmerge(idxlist):
             heapq.heapreplace(heap, (e, it))
         else:
             heapq.heappop(heap)
-    log('Reading indexes: %.2f%% (%d/%d), done.\n' % (100, total, total))
+    if final_progress:
+        log('Reading indexes: %.2f%% (%d/%d), done.\n' % (100, total, total))
 
 
 class PackWriter:

lib/bup/helpers.py

@@ -3,6 +3,17 @@
 from bup import _version
 
 
+def atoi(s):
+    """Convert the string 's' to an integer. Return 0 if s is not a number."""
+    try:
+        return int(s or '0')
+    except ValueError:
+        return 0
+
+
+buglvl = atoi(os.environ.get('BUP_DEBUG', 0))
+
+
 # Write (blockingly) to sockets that may or may not be in blocking mode.
 # We need this because our stderr is sometimes eaten by subprocesses
 # (probably ssh) that sometimes make it nonblocking, if only temporarily,
@@ -26,6 +37,16 @@ def log(s):
     _hard_write(sys.stderr.fileno(), s)
 
 
+def debug1(s):
+    if buglvl >= 1:
+        log(s)
+
+
+def debug2(s):
+    if buglvl >= 2:
+        log(s)
+
+
 def mkdirp(d, mode=None):
     """Recursively create directories on path 'd'.
 
@@ -305,14 +326,6 @@ def count(l):
     return reduce(lambda x,y: x+1, l)
 
 
-def atoi(s):
-    """Convert the string 's' to an integer. Return 0 if s is not a number."""
-    try:
-        return int(s or '0')
-    except ValueError:
-        return 0
-
-
 saved_errors = []
 def add_error(e):
     """Append an error message to the list of saved errors.

lib/bup/ssh.py

@@ -28,10 +28,11 @@ def connect(rhost, subcmd):
         # allow shellquoting.  So we end up having to double-shellquote
         # stuff here.
         escapedir = re.sub(r'([^\w/])', r'\\\\\\\1', nicedir)
+        buglvl = helpers.atoi(os.environ.get('BUP_DEBUG'))
         force_tty = helpers.atoi(os.environ.get('BUP_FORCE_TTY'))
         cmd = r"""
-                   sh -c PATH=%s:'$PATH BUP_FORCE_TTY=%s bup %s'
-               """ % (escapedir, force_tty, subcmd)
+                   sh -c PATH=%s:'$PATH BUP_DEBUG=%s BUP_FORCE_TTY=%s bup %s'
+               """ % (escapedir, buglvl, force_tty, subcmd)
         argv = ['ssh', rhost, '--', cmd.strip()]
         #helpers.log('argv is: %r\n' % argv)
     def setup():