Index: duplicity-bin
===================================================================
RCS file: /sources/duplicity/duplicity/duplicity-bin,v
retrieving revision 1.42
diff -u -p -r1.42 duplicity-bin
--- duplicity-bin	16 Nov 2008 18:48:13 -0000	1.42
+++ duplicity-bin	18 Nov 2008 02:29:53 -0000
@@ -156,6 +156,9 @@ def write_multivol(backup_type, tarblock
         async_waiters.append(io_scheduler.schedule_task(lambda tdp, dest_filename: put(tdp, dest_filename),
                                 (tdp, dest_filename)))
 
+        # Log human-readable version as well as raw numbers for machine consumers
+        log.Progress('Processed volume %d' % vol_num, diffdir.stats.SourceFileSize)
+
     # Collect byte count from all asynchronous jobs; also implicitly waits
     # for them all to complete.
     for waiter in async_waiters:
@@ -304,10 +307,14 @@ def restore_get_patched_rop_iter(col_sta
     def get_fileobj_iter(backup_set):
         """Get file object iterator from backup_set contain given index"""
         manifest = backup_set.get_manifest()
-        for vol_num in manifest.get_containing_volumes(index):
+        volumes = manifest.get_containing_volumes(index)
+        numvols = len(volumes)
+        for vol_num in volumes:
             yield restore_get_enc_fileobj(backup_set.backend,
                                           backup_set.volume_name_dict[vol_num],
                                           manifest.volume_info_dict[vol_num])
+            log.Progress('Processed volume %d of %d' % (vol_num, numvols),
+                         vol_num, numvols)
 
     fileobj_iters = map(get_fileobj_iter, backup_setlist)
     tarfiles = map(patchdir.TarFile_FromFileobjs, fileobj_iters)
Index: duplicity/diffdir.py
===================================================================
RCS file: /sources/duplicity/duplicity/duplicity/diffdir.py,v
retrieving revision 1.17
diff -u -p -r1.17 diffdir.py
--- duplicity/diffdir.py	16 Nov 2008 18:52:30 -0000	1.17
+++ duplicity/diffdir.py	18 Nov 2008 02:29:56 -0000
@@ -101,14 +101,16 @@ def get_delta_path(new_path, sig_path):
     delta_path = new_path.get_ropath()
     if not new_path.isreg():
         delta_path.difftype = "snapshot"
+        if stats:
+            stats.SourceFileSize += delta_path.getsize()
     elif not sig_path or not sig_path.isreg():
         delta_path.difftype = "snapshot"
-        delta_path.setfileobj(new_path.open("rb"))
+        delta_path.setfileobj(FileWithReadCounter(new_path.open("rb")))
     else:
         # both new and sig exist and are regular files
         assert sig_path.difftype == "signature"
         delta_path.difftype = "diff"
-        sigfp, newfp = sig_path.open("rb"), new_path.open("rb")
+        sigfp, newfp = sig_path.open("rb"), FileWithReadCounter(new_path.open("rb"))
         delta_path.setfileobj(librsync.DeltaFile(sigfp, newfp))
     new_path.copy_attribs(delta_path)
     delta_path.stat.st_size = new_path.stat.st_size     
@@ -356,7 +358,8 @@ def get_delta_path_w_sig(new_path, sig_p
     if new_path.isreg() and sig_path and sig_path.difftype == "signature":
         delta_path.difftype = "diff"
         old_sigfp = sig_path.open("rb")
-        newfp = FileWithSignature(new_path.open("rb"), callback,
+        counterfp = FileWithReadCounter(new_path.open("rb"))
+        newfp = FileWithSignature(counterfp, callback,
                                   new_path.getsize())
         delta_path.setfileobj(librsync.DeltaFile(old_sigfp, newfp))
     else:
@@ -364,8 +367,11 @@ def get_delta_path_w_sig(new_path, sig_p
         ti.name = "snapshot/" + "/".join(index) 
         if not new_path.isreg():
             sigTarFile.addfile(ti)
+            if stats:
+                stats.SourceFileSize += delta_path.getsize()
         else:
-            delta_path.setfileobj(FileWithSignature(new_path.open("rb"),
+            counterfp = FileWithReadCounter(new_path.open("rb"))
+            delta_path.setfileobj(FileWithSignature(counterfp,
                                                     callback,
                                                     new_path.getsize()))
     new_path.copy_attribs(delta_path)
@@ -373,6 +379,22 @@ def get_delta_path_w_sig(new_path, sig_p
     return delta_path
 
 
+class FileWithReadCounter:
+    """File-like object which also computes amount read as it is read"""
+    def __init__(self, infile):
+        """FileWithReadCounter initializer"""
+        self.infile = infile
+
+    def read(self, length = -1):
+        buf = self.infile.read(length)
+        if stats:
+            stats.SourceFileSize += len(buf)
+        return buf
+
+    def close(self):
+        return self.infile.close()
+
+
 class FileWithSignature:
     """File-like object which also computes signature as it is read"""
     blocksize = 32 * 1024
@@ -511,7 +533,11 @@ class DummyBlockIter(TarBlockIter):
             return self.tarinfo2tarblock(index, ti)
 
         if stats:
-            stats.RawDeltaSize += delta_ropath.getsize()
+            # Since we don't read the source files, we can't analyze them.
+            # Best we can do is count them raw.
+            stats.SourceFiles += 1
+            stats.SourceFileSize += delta_ropath.getsize()
+            log.Progress(None, stats.SourceFileSize)
         return self.tarinfo2tarblock(index, ti)
 
 
Index: duplicity/log.py
===================================================================
RCS file: /sources/duplicity/duplicity/duplicity/log.py,v
retrieving revision 1.9
diff -u -p -r1.9 log.py
--- duplicity/log.py	16 Nov 2008 18:48:14 -0000	1.9
+++ duplicity/log.py	18 Nov 2008 02:29:57 -0000
@@ -45,22 +45,42 @@ def LoggerToDupLevel(verb):
        more severe"""
     return DupToLoggerLevel(verb)
 
-def Log(s, verb_level, code=1):
+def Log(s, verb_level, code=1, extra=None):
     """Write s to stderr if verbosity level low enough"""
     global _logger
-    # currentCode is a terrible hack until duplicity depends on Python 2.5
+    # controlLine is a terrible hack until duplicity depends on Python 2.5
     # and its logging 'extra' keyword that allows a custom record dictionary.
-    _logger.currentCode = code
+    if extra:
+        _logger.controlLine = '%d %s' % (code, extra)
+    else:
+        _logger.controlLine = '%d' % (code)
+    if not s:
+        s = '' # If None is passed, standard logging would render it as 'None'
     _logger.log(DupToLoggerLevel(verb_level), s)
-    _logger.currentCode = 1
+    _logger.controlLine = None
 
 def Debug(s):
     """Shortcut used for debug message (verbosity 9)."""
     Log(s, DEBUG)
 
-def Info(s):
+class InfoCode:
+    """Enumeration class to hold info code values.
+       These values should never change, as frontends rely upon them.
+       Don't use 0 or negative numbers."""
+    generic = 1
+    progress = 2
+
+def Info(s, code=InfoCode.generic):
     """Shortcut used for info messages (verbosity 5)."""
-    Log(s, INFO)
+    Log(s, INFO, code)
+
+def Progress(s, current, total=None):
+    """Shortcut used for progress messages (verbosity 5)."""
+    if total:
+        controlLine = '%d %d' % (current, total)
+    else:
+        controlLine = '%d' % current
+    Log(s, INFO, InfoCode.progress, controlLine)
 
 def Notice(s):
     """Shortcut used for notice messages (verbosity 3, the default)."""
@@ -97,28 +117,28 @@ def FatalError(s, code=ErrorCode.generic
 
 class DupLogRecord(logging.LogRecord):
     """Custom log record that holds a message code"""
-    def __init__(self, code, *args, **kwargs):
+    def __init__(self, controlLine, *args, **kwargs):
         global _logger
         logging.LogRecord.__init__(self, *args, **kwargs)
-        self.code = code
+        self.controlLine = controlLine
 
 class DupLogger(logging.Logger):
     """Custom logger that creates special code-bearing records"""
-    # currentCode is a terrible hack until duplicity depends on Python 2.5
+    # controlLine is a terrible hack until duplicity depends on Python 2.5
     # and its logging 'extra' keyword that allows a custom record dictionary.
-    currentCode = 1
+    controlLine = None
     def makeRecord(self, name, lvl, fn, lno, msg, args, exc_info, *argv, **kwargs):
-        return DupLogRecord(self.currentCode, name, lvl, fn, lno, msg, args, exc_info)
+        return DupLogRecord(self.controlLine, name, lvl, fn, lno, msg, args, exc_info)
 
 class OutFilter(logging.Filter):
     """Filter that only allows warning or less important messages"""
     def filter(self, record):
-        return record.levelno <= DupToLoggerLevel(WARNING)
+        return record.msg and record.levelno <= DupToLoggerLevel(WARNING)
 
 class ErrFilter(logging.Filter):
     """Filter that only allows messages more important than warnings"""
     def filter(self, record):
-        return record.levelno > DupToLoggerLevel(WARNING)
+        return record.msg and record.levelno > DupToLoggerLevel(WARNING)
 
 def setup():
     """Initialize logging"""
@@ -152,14 +172,15 @@ class MachineFormatter(logging.Formatter
     """Formatter that creates messages in a syntax easily consumable by other
        processes."""
     def __init__(self):
-        logging.Formatter.__init__(self, "%(levelname)s %(code)s\n%(message)s")
+        logging.Formatter.__init__(self, "%(levelname)s %(controlLine)s\n%(message)s")
     
     def format(self, record):
         s = logging.Formatter.format(self, record)
         # Indent each extra line with a dot and space so that the consumer
         # knows it's a continuation, not a new message.  Add a newline so
         # consumers know the message is over.
-        return s.replace('\n', '\n. ') + '\n'
+        # We rstrip in case 'message' was empty.
+        return s.rstrip().replace('\n', '\n. ') + '\n'
 
 class MachineFilter(logging.Filter):
     """Filter that only allows levels that are consumable by other processes."""
Index: duplicity/statistics.py
===================================================================
RCS file: /sources/duplicity/duplicity/duplicity/statistics.py,v
retrieving revision 1.4
diff -u -p -r1.4 statistics.py
--- duplicity/statistics.py	16 Nov 2008 18:48:15 -0000	1.4
+++ duplicity/statistics.py	18 Nov 2008 02:29:59 -0000
@@ -261,7 +261,7 @@ class StatsDeltaProcess(StatsObj):
         """Add stats of new file path to statistics"""
         filesize = path.getsize()
         self.SourceFiles += 1
-        self.SourceFileSize += filesize
+        # SourceFileSize is added-to incrementally as read
         self.NewFiles += 1
         self.NewFileSize += filesize
         self.DeltaEntries += 1
@@ -270,7 +270,7 @@ class StatsDeltaProcess(StatsObj):
         """Add stats of file that has changed since last backup"""
         filesize = path.getsize()
         self.SourceFiles += 1
-        self.SourceFileSize += filesize
+        # SourceFileSize is added-to incrementally as read
         self.ChangedFiles += 1
         self.ChangedFileSize += filesize
         self.DeltaEntries += 1
