convert from print() to logging

borg/archive.py

@@ -1,9 +1,15 @@
+from binascii import hexlify
 from datetime import datetime
 from getpass import getuser
 from itertools import groupby
 import errno
+import logging
+
+from .logger import create_logger
+logger = create_logger()
 from .key import key_factory
 from .remote import cache_if_remote
+
 import msgpack
 import os
 import socket
@@ -15,7 +21,7 @@
 from .platform import acl_get, acl_set
 from .chunker import Chunker
 from .hashindex import ChunkIndex
-from .helpers import parse_timestamp, Error, uid2user, user2uid, gid2group, group2gid, \
+from .helpers import parse_timestamp, format_timedelta, Error, uid2user, user2uid, gid2group, group2gid, \
     Manifest, Statistics, decode_dict, st_mtime_ns, make_path_safe, StableDict, int_to_bigint, bigint_to_int
 
 ITEMS_BUFFER = 1024 * 1024
@@ -127,7 +133,8 @@ class IncompatibleFilesystemEncodingError(Error):
 
     def __init__(self, repository, key, manifest, name, cache=None, create=False,
                  checkpoint_interval=300, numeric_owner=False, progress=False,
-                 chunker_params=CHUNKER_PARAMS):
+                 chunker_params=CHUNKER_PARAMS,
+                 start=datetime.now(), end=datetime.now()):
         self.cwd = os.getcwd()
         self.key = key
         self.repository = repository
@@ -140,6 +147,8 @@ def __init__(self, repository, key, manifest, name, cache=None, create=False,
         self.name = name
         self.checkpoint_interval = checkpoint_interval
         self.numeric_owner = numeric_owner
+        self.start = start
+        self.end = end
         self.pipeline = DownloadPipeline(self.repository, self.key)
         if create:
             self.items_buffer = CacheChunkBuffer(self.cache, self.key, self.stats, chunker_params)
@@ -179,6 +188,24 @@ def ts(self):
         """Timestamp of archive creation in UTC"""
         return parse_timestamp(self.metadata[b'time'])
 
+    @property
+    def fpr(self):
+        return hexlify(self.id).decode('ascii')
+
+    @property
+    def duration(self):
+        return format_timedelta(self.end-self.start)
+
+    def __str__(self):
+        buf = '''Archive name: {0.name}
+Archive fingerprint: {0.fpr}
+Start time: {0.start:%c}
+End time: {0.end:%c}
+Duration: {0.duration}
+Number of files: {0.stats.nfiles}
+{0.cache}'''.format(self)
+        return buf
+
     def __repr__(self):
         return 'Archive(%r)' % self.name
 
@@ -628,7 +655,7 @@ def check(self, repository, repair=False, archive=None, last=None):
         self.orphan_chunks_check()
         self.finish()
         if not self.error_found:
-            self.report_progress('Archive consistency check complete, no problems found.')
+            logger.info('Archive consistency check complete, no problems found.')
         return self.repair or not self.error_found
 
     def init_chunks(self):
@@ -650,7 +677,7 @@ def init_chunks(self):
     def report_progress(self, msg, error=False):
         if error:
             self.error_found = True
-        print(msg, file=sys.stderr if error else sys.stdout)
+        logger.log(logging.ERROR if error else logging.WARNING, msg)
 
     def identify_key(self, repository):
         cdata = repository.get(next(self.chunks.iteritems())[0])
@@ -777,7 +804,7 @@ def missing_chunk_detector(chunk_id):
             num_archives = 1
             end = 1
         for i, (name, info) in enumerate(archive_items[:end]):
-            self.report_progress('Analyzing archive {} ({}/{})'.format(name, num_archives - i, num_archives))
+            logger.info('Analyzing archive {} ({}/{})'.format(name, num_archives - i, num_archives))
             archive_id = info[b'id']
             if archive_id not in self.chunks:
                 self.report_progress('Archive metadata block is missing', error=True)

borg/archiver.py

@@ -7,6 +7,7 @@
 import functools
 import inspect
 import io
+
 import os
 import signal
 import stat
@@ -17,6 +18,8 @@
 from . import __version__
 from .archive import Archive, ArchiveChecker, CHUNKER_PARAMS
 from .compress import Compressor, COMPR_BUFFER
+from .logger import create_logger, setup_logging
+logger = create_logger()
 from .upgrader import AtticRepositoryUpgrader
 from .repository import Repository
 from .cache import Cache
@@ -47,15 +50,11 @@ def open_repository(self, location, create=False, exclusive=False):
     def print_error(self, msg, *args):
         msg = args and msg % args or msg
         self.exit_code = 1
-        print('borg: ' + msg, file=sys.stderr)
+        logger.error('borg: ' + msg)
 
     def print_verbose(self, msg, *args, **kw):
-        if self.verbose:
-            msg = args and msg % args or msg
-            if kw.get('newline', True):
-                print(msg)
-            else:
-                print(msg, end=' ')
+        msg = args and msg % args or msg
+        logger.info(msg)
 
     def do_serve(self, args):
         """Start in server mode. This command is usually not used manually.
@@ -64,7 +63,7 @@ def do_serve(self, args):
 
     def do_init(self, args):
         """Initialize an empty repository"""
-        print('Initializing repository at "%s"' % args.repository.orig)
+        logger.info('Initializing repository at "%s"' % args.repository.orig)
         repository = self.open_repository(args.repository, create=True, exclusive=True)
         key = key_creator(repository, args)
         manifest = Manifest(key, repository)
@@ -86,9 +85,9 @@ def do_check(self, args):
                 if input('Do you want to continue? ') == 'Yes I am sure':
                     break
         if not args.archives_only:
-            print('Starting repository check...')
+            logger.warning('Starting repository check...')
             if repository.check(repair=args.repair):
-                print('Repository check complete, no problems found.')
+                logger.info('Repository check complete, no problems found.')
             else:
                 return 1
         if not args.repo_only and not ArchiveChecker().check(
@@ -117,7 +116,7 @@ def do_create(self, args):
             archive = Archive(repository, key, manifest, args.archive.archive, cache=cache,
                               create=True, checkpoint_interval=args.checkpoint_interval,
                               numeric_owner=args.numeric_owner, progress=args.progress,
-                              chunker_params=args.chunker_params)
+                              chunker_params=args.chunker_params, start=t0)
         else:
             archive = cache = None
         # Add cache dir to inode_skip list
@@ -162,16 +161,10 @@ def do_create(self, args):
             if args.progress:
                 archive.stats.show_progress(final=True)
             if args.stats:
-                t = datetime.now()
-                diff = t - t0
+                archive.end = datetime.now()
                 print('-' * 78)
-                print('Archive name: %s' % args.archive.archive)
-                print('Archive fingerprint: %s' % hexlify(archive.id).decode('ascii'))
-                print('Start time: %s' % t0.strftime('%c'))
-                print('End time: %s' % t.strftime('%c'))
-                print('Duration: %s' % format_timedelta(diff))
-                print('Number of files: %d' % archive.stats.nfiles)
-                archive.stats.print_('This archive:', cache)
+                print(str(archive))
+                print(archive.stats.print_('This archive:', cache))
                 print('-' * 78)
         return self.exit_code
 
@@ -251,7 +244,7 @@ def do_extract(self, args):
         """Extract archive contents"""
         # be restrictive when restoring files, restore permissions later
         if sys.getfilesystemencoding() == 'ascii':
-            print('Warning: File system encoding is "ascii", extracting non-ascii filenames will not be supported.')
+            logger.warning('Warning: File system encoding is "ascii", extracting non-ascii filenames will not be supported.')
         repository = self.open_repository(args.archive)
         manifest, key = Manifest.load(repository)
         archive = Archive(repository, key, manifest, args.archive.archive,
@@ -317,21 +310,22 @@ def do_delete(self, args):
             repository.commit()
             cache.commit()
             if args.stats:
-                stats.print_('Deleted data:', cache)
+                logger.info(stats.print_('Deleted data:', cache))
         else:
             if not args.cache_only:
-                print("You requested to completely DELETE the repository *including* all archives it contains:")
+                print("You requested to completely DELETE the repository *including* all archives it contains:", file=sys.stderr)
                 for archive_info in manifest.list_archive_infos(sort_by='ts'):
-                    print(format_archive(archive_info))
+                    print(format_archive(archive_info), file=sys.stderr)
                 if not os.environ.get('BORG_CHECK_I_KNOW_WHAT_I_AM_DOING'):
-                    print("""Type "YES" if you understand this and want to continue.\n""")
+                    print("""Type "YES" if you understand this and want to continue.\n""", file=sys.stderr)
+                    # XXX: prompt may end up on stdout, but we'll assume that input() does the right thing
                     if input('Do you want to continue? ') != 'YES':
                         self.exit_code = 1
                         return self.exit_code
                 repository.destroy()
-                print("Repository deleted.")
+                logger.info("Repository deleted.")
             cache.destroy()
-            print("Cache deleted.")
+            logger.info("Cache deleted.")
         return self.exit_code
 
     def do_mount(self, args):
@@ -417,7 +411,7 @@ def do_info(self, args):
         print('Time: %s' % to_localtime(archive.ts).strftime('%c'))
         print('Command line:', remove_surrogates(' '.join(archive.metadata[b'cmdline'])))
         print('Number of files: %d' % stats.nfiles)
-        stats.print_('This archive:', cache)
+        print(stats.print_('This archive:', cache))
         return self.exit_code
 
     def do_prune(self, args):
@@ -462,7 +456,7 @@ def do_prune(self, args):
             repository.commit()
             cache.commit()
         if args.stats:
-            stats.print_('Deleted data:', cache)
+            logger.info(stats.print_('Deleted data:', cache))
         return self.exit_code
 
     def do_upgrade(self, args):
@@ -566,9 +560,8 @@ def run(self, args=None):
                     #       http://www.brynosaurus.com/cachedir/
                     """).lstrip())
         common_parser = argparse.ArgumentParser(add_help=False)
-        common_parser.add_argument('-v', '--verbose', dest='verbose', action='store_true',
-                                   default=False,
-                                   help='verbose output')
+        common_parser.add_argument('-v', '--verbose', dest='verbose', action='count',
+                                   help='verbose output, defaults to warnings only')
         common_parser.add_argument('--no-files-cache', dest='cache_files', action='store_false',
                                    help='do not load/update the file metadata cache used to detect unchanged files')
         common_parser.add_argument('--umask', dest='umask', type=lambda s: int(s, 8), default=0o077, metavar='M',
@@ -978,7 +971,7 @@ def run(self, args=None):
                                help='additional help on TOPIC')
 
         args = parser.parse_args(args or ['-h'])
-        self.verbose = args.verbose
+        setup_logging(args)
         os.umask(args.umask)
         RemoteRepository.remote_path = args.remote_path
         RemoteRepository.umask = args.umask
@@ -997,15 +990,15 @@ def sig_info_handler(signum, stack):  # pragma: no cover
                 total = loc['st'].st_size
             except Exception:
                 pos, total = 0, 0
-            print("{0} {1}/{2}".format(path, format_file_size(pos), format_file_size(total)))
+            logger.warning("{0} {1}/{2}".format(path, format_file_size(pos), format_file_size(total)))
             break
         if func in ('extract_item', ):  # extract op
             path = loc['item'][b'path']
             try:
                 pos = loc['fd'].tell()
             except Exception:
                 pos = 0
-            print("{0} {1}/???".format(path, format_file_size(pos)))
+            logger.warning("{0} {1}/???".format(path, format_file_size(pos)))
             break
 
 

borg/cache.py

@@ -1,6 +1,8 @@
 import configparser
 from .remote import cache_if_remote
+from collections import namedtuple
 import errno
+
 import msgpack
 import os
 import stat
@@ -11,8 +13,10 @@
 import tempfile
 
 from .key import PlaintextKey
+from .logger import create_logger
+logger = create_logger()
 from .helpers import Error, get_cache_dir, decode_dict, st_mtime_ns, unhexlify, int_to_bigint, \
-    bigint_to_int
+    bigint_to_int, format_file_size
 from .locking import UpgradableLock
 from .hashindex import ChunkIndex
 
@@ -70,10 +74,25 @@ def __init__(self, repository, key, manifest, path=None, sync=True, do_files=Fal
     def __del__(self):
         self.close()
 
+    def __str__(self):
+        return format(self, """All archives:   {0.total_size:>20s} {0.total_csize:>20s} {0.unique_csize:>20s}
+
+                       Unique chunks         Total chunks
+Chunk index:    {0.total_unique_chunks:20d} {0.total_chunks:20d}""")
+
+    def __format__(self, format_spec):
+        # XXX: this should really be moved down to `hashindex.pyx`
+        Summary = namedtuple('Summary', ['total_size', 'total_csize', 'unique_size', 'unique_csize', 'total_unique_chunks', 'total_chunks'])
+        stats = Summary(*self.chunks.summarize())._asdict()
+        for field in ['total_size', 'total_csize', 'unique_csize']:
+            stats[field] = format_file_size(stats[field])
+        stats = Summary(**stats)
+        return format_spec.format(stats)
+
     def _confirm(self, message, env_var_override=None):
         print(message, file=sys.stderr)
         if env_var_override and os.environ.get(env_var_override):
-            print("Yes (From {})".format(env_var_override))
+            print("Yes (From {})".format(env_var_override), file=sys.stderr)
             return True
         if not sys.stdin.isatty():
             return False
@@ -263,7 +282,7 @@ def fetch_and_build_idx(archive_id, repository, key):
                 unpacker.feed(data)
                 for item in unpacker:
                     if not isinstance(item, dict):
-                        print('Error: Did not get expected metadata dict - archive corrupted!')
+                        logger.error('Error: Did not get expected metadata dict - archive corrupted!')
                         continue
                     if b'chunks' in item:
                         for chunk_id, size, csize in item[b'chunks']:
@@ -285,10 +304,10 @@ def lookup_name(archive_id):
                     return name
 
         def create_master_idx(chunk_idx):
-            print('Synchronizing chunks cache...')
+            logger.info('Synchronizing chunks cache...')
             cached_ids = cached_archives()
             archive_ids = repo_archives()
-            print('Archives: %d, w/ cached Idx: %d, w/ outdated Idx: %d, w/o cached Idx: %d.' % (
+            logger.info('Archives: %d, w/ cached Idx: %d, w/ outdated Idx: %d, w/o cached Idx: %d.' % (
                 len(archive_ids), len(cached_ids),
                 len(cached_ids - archive_ids), len(archive_ids - cached_ids), ))
             # deallocates old hashindex, creates empty hashindex:
@@ -300,20 +319,20 @@ def create_master_idx(chunk_idx):
                     archive_name = lookup_name(archive_id)
                     if archive_id in cached_ids:
                         archive_chunk_idx_path = mkpath(archive_id)
-                        print("Reading cached archive chunk index for %s ..." % archive_name)
+                        logger.info("Reading cached archive chunk index for %s ..." % archive_name)
                         archive_chunk_idx = ChunkIndex.read(archive_chunk_idx_path)
                     else:
-                        print('Fetching and building archive index for %s ...' % archive_name)
+                        logger.info('Fetching and building archive index for %s ...' % archive_name)
                         archive_chunk_idx = fetch_and_build_idx(archive_id, repository, self.key)
-                    print("Merging into master chunks index ...")
+                    logger.info("Merging into master chunks index ...")
                     if chunk_idx is None:
                         # we just use the first archive's idx as starting point,
                         # to avoid growing the hash table from 0 size and also
                         # to save 1 merge call.
                         chunk_idx = archive_chunk_idx
                     else:
                         chunk_idx.merge(archive_chunk_idx)
-            print('Done.')
+            logger.info('Done.')
             return chunk_idx
 
         def legacy_cleanup():