From e3d646243627020f5b99e6d7a0b78e2584b422d1 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Mon, 6 Sep 2010 18:00:57 -0700 Subject: [PATCH] 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 --- cmd/midx-cmd.py | 51 +++++++++++++++++++++++++++------------------- cmd/server-cmd.py | 22 ++++++++++---------- lib/bup/client.py | 12 +++++------ lib/bup/git.py | 11 +++++----- lib/bup/helpers.py | 29 ++++++++++++++++++-------- lib/bup/ssh.py | 5 +++-- lib/bup/vfs.py | 10 ++++----- main.py | 18 +++++++++------- 8 files changed, 93 insertions(+), 65 deletions(-) diff --git a/cmd/midx-cmd.py b/cmd/midx-cmd.py index eb66759..f5e91e7 100755 --- a/cmd/midx-cmd.py +++ b/cmd/midx-cmd.py @@ -12,6 +12,7 @@ bup midx [options...] 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,7 +197,7 @@ if opt.max_files < 0: 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] @@ -196,8 +205,8 @@ elif opt.auto or opt.force: 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") diff --git a/cmd/server-cmd.py b/cmd/server-cmd.py index 5acc98a..8ea3a37 100755 --- a/cmd/server-cmd.py +++ b/cmd/server-cmd.py @@ -8,13 +8,13 @@ suspended_w = None 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 @@ o = options.Options('bup server', optspec) 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 @@ for _line in lr: 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 @@ for _line in lr: else: raise Exception('unknown server command: %r\n' % line) -log('bup server: done\n') +debug1('bup server: done\n') diff --git a/lib/bup/client.py b/lib/bup/client.py index 8c6ef59..d1fdbbe 100644 --- a/lib/bup/client.py +++ b/lib/bup/client.py @@ -134,11 +134,11 @@ class Client: 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 @@ class Client: 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 @@ class Client: 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') diff --git a/lib/bup/git.py b/lib/bup/git.py index df1678a..af54a60 100644 --- a/lib/bup/git.py +++ b/lib/bup/git.py @@ -383,8 +383,8 @@ class PackIdxList: 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) @@ -392,7 +392,7 @@ class PackIdxList: 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: diff --git a/lib/bup/helpers.py b/lib/bup/helpers.py index daaa0c4..3406700 100644 --- a/lib/bup/helpers.py +++ b/lib/bup/helpers.py @@ -3,6 +3,17 @@ import sys, os, pwd, subprocess, errno, socket, select, mmap, stat, re 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. diff --git a/lib/bup/ssh.py b/lib/bup/ssh.py index 99053ff..52ee035 100644 --- a/lib/bup/ssh.py +++ b/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(): diff --git a/lib/bup/vfs.py b/lib/bup/vfs.py index 1e61745..479a905 100644 --- a/lib/bup/vfs.py +++ b/lib/bup/vfs.py @@ -120,7 +120,7 @@ class _ChunkReader(object): self.blob = self.blob[want:] if not self.it: break - log('next(%d) returned %d\n' % (size, len(out))) + debug2('next(%d) returned %d\n' % (size, len(out))) self.ofs += len(out) return out @@ -220,7 +220,7 @@ class Node(object): return self def _lresolve(self, parts): - #log('_lresolve %r in %r\n' % (parts, self.name)) + #debug2('_lresolve %r in %r\n' % (parts, self.name)) if not parts: return self (first, rest) = (parts[0], parts[1:]) @@ -253,7 +253,7 @@ class Node(object): parts = re.split(r'/+', path or '.') if not parts[-1]: parts[-1] = '.' - #log('parts: %r %r\n' % (path, parts)) + #debug2('parts: %r %r\n' % (path, parts)) return start._lresolve(parts) def resolve(self, path = ''): @@ -310,12 +310,12 @@ class File(Node): def size(self): """Get this file's size.""" if self._cached_size == None: - log('<<< [options...]\n\n') common = dict( ftp = 'Browse backup sets using an ftp-like client', fsck = 'Check backup sets for damage and add redundancy information', @@ -65,8 +66,8 @@ if len(argv) < 2: # Handle global options. try: - global_args, subcmd = getopt.getopt(argv[1:], '?Vd:', - ['help', 'version', 'bup-dir=']) + global_args, subcmd = getopt.getopt(argv[1:], '?VDd:', + ['help', 'version', 'debug', 'bup-dir=']) except getopt.GetoptError, ex: log('error: ' + ex.msg + '\n') usage() @@ -75,11 +76,14 @@ help_requested = None dest_dir = None for opt in global_args: - if opt[0] == '-?' or opt[0] == '--help': + if opt[0] in ['-?', '--help']: help_requested = True - if opt[0] == '-V' or opt[0] == '--version': + elif opt[0] in ['-V', '--version']: subcmd = ['version'] - elif opt[0] == '-d' or opt[0] == '--bup-dir': + elif opt[0] in ['-D', '--debug']: + helpers.buglvl += 1 + os.environ['BUP_DEBUG'] = str(helpers.buglvl) + elif opt[0] in ['-d', '--bup-dir']: dest_dir = opt[1] else: log('error: unexpected option "%s"\n' % opt[0]) -- 2.39.2