From 6288c9f7511607842e79ef08ede821f91e9e5f74 Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Mon, 27 Feb 2017 20:30:20 +0100
Subject: [PATCH 01/10] enhance JSON progress information

separate output types, extra information
---
 docs/internals/frontends.rst | 27 +++++++++++++++
 src/borg/helpers.py          | 64 +++++++++++++++++++++++++++---------
 2 files changed, 76 insertions(+), 15 deletions(-)

diff --git a/docs/internals/frontends.rst b/docs/internals/frontends.rst
index 5d17d2e93..b6bc18dc0 100644
--- a/docs/internals/frontends.rst
+++ b/docs/internals/frontends.rst
@@ -39,6 +39,33 @@ archive_progress
     path
         Current path
 
+progress_message
+    A message-based progress information with no concrete progress information, just a message
+    saying what is currently worked on.
+
+    operation
+        integer ID of the operation
+    finished
+        boolean indicating whether the operation has finished, only the last object for an *operation*
+        can have this property set to *true*.
+    message
+        current progress message (may be empty/absent)
+
+progress_percent
+    Absolute progress display with defined end/total and current value.
+
+    operation
+        integer ID of the operation
+    finished
+        boolean indicating whether the operation has finished, only the last object for an *operation*
+        can have this property set to *true*.
+    message
+        A formatted progress message, this will include the percentage and perhaps other information
+    current
+        Current value (always less-or-equal to *total*)
+    total
+        Total value
+
 file_status
     This is only output by :ref:`borg_create` and :ref:`borg_recreate` if ``--list`` is specified. The usual
     rules for the file listing applies, including the ``--filter`` option.
diff --git a/src/borg/helpers.py b/src/borg/helpers.py
index 8f1e9cbca..7f2a4e670 100644
--- a/src/borg/helpers.py
+++ b/src/borg/helpers.py
@@ -1377,10 +1377,20 @@ def ellipsis_truncate(msg, space):
 
 class ProgressIndicatorBase:
     LOGGER = 'borg.output.progress'
+    JSON_TYPE = None
+    json = False
+
+    operation_id_counter = 0
+
+    @classmethod
+    def operation_id(cls):
+        cls.operation_id_counter += 1
+        return cls.operation_id_counter
 
     def __init__(self):
         self.handler = None
         self.logger = logging.getLogger(self.LOGGER)
+        self.id = self.operation_id()
 
         # If there are no handlers, set one up explicitly because the
         # terminator and propagation needs to be set.  If there are,
@@ -1394,6 +1404,7 @@ class ProgressIndicatorBase:
             try:
                 formatter = logger.formatter
                 terminator = '\n' if logger.json else '\r'
+                self.json = logger.json
             except AttributeError:
                 terminator = '\r'
             else:
@@ -1404,12 +1415,30 @@ class ProgressIndicatorBase:
             if self.logger.level == logging.NOTSET:
                 self.logger.setLevel(logging.WARN)
             self.logger.propagate = False
+        self.emit = self.logger.getEffectiveLevel() == logging.INFO
 
     def __del__(self):
         if self.handler is not None:
             self.logger.removeHandler(self.handler)
             self.handler.close()
 
+    def output_json(self, *, finished=False, **kwargs):
+        assert self.json
+        if not self.emit:
+            return
+        print(json.dumps(dict(
+            operation=self.id,
+            type=self.JSON_TYPE,
+            finished=finished,
+            **kwargs,
+        )), file=sys.stderr)
+
+    def finish(self):
+        if self.json:
+            self.output_json(finished=True)
+        else:
+            self.output('')
+
 
 def justify_to_terminal_size(message):
     terminal_space = get_terminal_size(fallback=(-1, -1))[0]
@@ -1420,14 +1449,18 @@ def justify_to_terminal_size(message):
 
 
 class ProgressIndicatorMessage(ProgressIndicatorBase):
-    def output(self, msg):
-        self.logger.info(justify_to_terminal_size(msg))
+    JSON_TYPE = 'progress_message'
 
-    def finish(self):
-        self.output('')
+    def output(self, msg):
+        if self.json:
+            self.output_json(message=msg)
+        else:
+            self.logger.info(justify_to_terminal_size(msg))
 
 
 class ProgressIndicatorPercent(ProgressIndicatorBase):
+    JSON_TYPE = 'progress_percent'
+
     def __init__(self, total=0, step=5, start=0, msg="%3.0f%%"):
         """
         Percentage-based progress indicator
@@ -1466,22 +1499,23 @@ class ProgressIndicatorPercent(ProgressIndicatorBase):
         if pct is not None:
             # truncate the last argument, if no space is available
             if info is not None:
-                # no need to truncate if we're not outputing to a terminal
-                terminal_space = get_terminal_size(fallback=(-1, -1))[0]
-                if terminal_space != -1:
-                    space = terminal_space - len(self.msg % tuple([pct] + info[:-1] + ['']))
-                    info[-1] = ellipsis_truncate(info[-1], space)
+                if not self.json:
+                    # no need to truncate if we're not outputing to a terminal
+                    terminal_space = get_terminal_size(fallback=(-1, -1))[0]
+                    if terminal_space != -1:
+                        space = terminal_space - len(self.msg % tuple([pct] + info[:-1] + ['']))
+                        info[-1] = ellipsis_truncate(info[-1], space)
                 return self.output(self.msg % tuple([pct] + info), justify=False)
 
             return self.output(self.msg % pct)
 
     def output(self, message, justify=True):
-        if justify:
-            message = justify_to_terminal_size(message)
-        self.logger.info(message)
-
-    def finish(self):
-        self.output('')
+        if self.json:
+            self.output_json(message=message, current=self.counter, total=self.total)
+        else:
+            if justify:
+                message = justify_to_terminal_size(message)
+            self.logger.info(message)
 
 
 class ProgressIndicatorEndless:

From d5515b69529720d1686ff298ad340e3ab4ce5795 Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Mon, 27 Feb 2017 20:38:02 +0100
Subject: [PATCH 02/10] add msgid to progress output

---
 docs/internals/frontends.rst | 12 ++++++++----
 src/borg/archive.py          |  5 +++--
 src/borg/archiver.py         |  5 +++--
 src/borg/cache.py            |  7 ++++---
 src/borg/helpers.py          | 17 ++++++++++-------
 src/borg/repository.py       |  9 ++++++---
 6 files changed, 34 insertions(+), 21 deletions(-)

diff --git a/docs/internals/frontends.rst b/docs/internals/frontends.rst
index b6bc18dc0..e11a1a3f4 100644
--- a/docs/internals/frontends.rst
+++ b/docs/internals/frontends.rst
@@ -44,7 +44,9 @@ progress_message
     saying what is currently worked on.
 
     operation
-        integer ID of the operation
+        unique, opaque integer ID of the operation
+    msgid
+        Message ID of the operation (may be *none*)
     finished
         boolean indicating whether the operation has finished, only the last object for an *operation*
         can have this property set to *true*.
@@ -52,10 +54,12 @@ progress_message
         current progress message (may be empty/absent)
 
 progress_percent
-    Absolute progress display with defined end/total and current value.
+    Absolute progress information with defined end/total and current value.
 
     operation
-        integer ID of the operation
+        unique, opaque integer ID of the operation
+    msgid
+        Message ID of the operation (may be *none*)
     finished
         boolean indicating whether the operation has finished, only the last object for an *operation*
         can have this property set to *true*.
@@ -81,7 +85,7 @@ log_message
     created
         Unix timestamp (float)
     levelname
-        Upper-case log level name (also called severity). Defined levels are: DEBUG, INFO, WARNING, CRITICAL
+        Upper-case log level name (also called severity). Defined levels are: DEBUG, INFO, WARNING, ERROR, CRITICAL
     name
         Name of the emitting entity
     message
diff --git a/src/borg/archive.py b/src/borg/archive.py
index 1df1401de..6fc0739e2 100644
--- a/src/borg/archive.py
+++ b/src/borg/archive.py
@@ -734,7 +734,7 @@ Utilization of max. archive size: {csize_max:.0%}
         try:
             unpacker = msgpack.Unpacker(use_list=False)
             items_ids = self.metadata.items
-            pi = ProgressIndicatorPercent(total=len(items_ids), msg="Decrementing references %3.0f%%")
+            pi = ProgressIndicatorPercent(total=len(items_ids), msg="Decrementing references %3.0f%%", msgid='archive.delete')
             for (i, (items_id, data)) in enumerate(zip(items_ids, self.repository.get_many(items_ids))):
                 if progress:
                     pi.show(i)
@@ -1153,7 +1153,8 @@ class ArchiveChecker:
         chunks_count_segments = 0
         errors = 0
         defect_chunks = []
-        pi = ProgressIndicatorPercent(total=chunks_count_index, msg="Verifying data %6.2f%%", step=0.01)
+        pi = ProgressIndicatorPercent(total=chunks_count_index, msg="Verifying data %6.2f%%", step=0.01,
+                                      msgid='check.verify_data')
         marker = None
         while True:
             chunk_ids = self.repository.scan(limit=100, marker=marker)
diff --git a/src/borg/archiver.py b/src/borg/archiver.py
index 243e91d2d..ad8a286d8 100644
--- a/src/borg/archiver.py
+++ b/src/borg/archiver.py
@@ -555,7 +555,7 @@ class Archiver:
 
         filter = self.build_filter(matcher, peek_and_store_hardlink_masters, strip_components)
         if progress:
-            pi = ProgressIndicatorPercent(msg='%5.1f%% Extracting: %s', step=0.1)
+            pi = ProgressIndicatorPercent(msg='%5.1f%% Extracting: %s', step=0.1, msgid='extract')
             pi.output('Calculating size')
             extracted_size = sum(item.get_size(hardlink_masters) for item in archive.iter_items(filter))
             pi.total = extracted_size
@@ -589,7 +589,8 @@ class Archiver:
                 self.print_warning('%s: %s', remove_surrogates(orig_path), e)
 
         if not args.dry_run:
-            pi = ProgressIndicatorPercent(total=len(dirs), msg='Setting directory permissions %3.0f%%')
+            pi = ProgressIndicatorPercent(total=len(dirs), msg='Setting directory permissions %3.0f%%',
+                                          msgid='extract.permissions')
             while dirs:
                 pi.show()
                 dir_item = dirs.pop(-1)
diff --git a/src/borg/cache.py b/src/borg/cache.py
index 504001e7a..56e165609 100644
--- a/src/borg/cache.py
+++ b/src/borg/cache.py
@@ -320,7 +320,7 @@ Chunk index:    {0.total_unique_chunks:20d} {0.total_chunks:20d}"""
 
     def begin_txn(self):
         # Initialize transaction snapshot
-        pi = ProgressIndicatorMessage()
+        pi = ProgressIndicatorMessage(msgid='cache.begin_transaction')
         txn_dir = os.path.join(self.path, 'txn.tmp')
         os.mkdir(txn_dir)
         pi.output('Initializing cache transaction: Reading config')
@@ -340,7 +340,7 @@ Chunk index:    {0.total_unique_chunks:20d} {0.total_chunks:20d}"""
         if not self.txn_active:
             return
         self.security_manager.save(self.manifest, self.key, self)
-        pi = ProgressIndicatorMessage()
+        pi = ProgressIndicatorMessage(msgid='cache.commit')
         if self.files is not None:
             if self._newest_mtime is None:
                 # was never set because no files were modified/added
@@ -468,7 +468,8 @@ Chunk index:    {0.total_unique_chunks:20d} {0.total_chunks:20d}"""
                 chunk_idx = None
                 if self.progress:
                     pi = ProgressIndicatorPercent(total=len(archive_ids), step=0.1,
-                                                  msg='%3.0f%% Syncing chunks cache. Processing archive %s')
+                                                  msg='%3.0f%% Syncing chunks cache. Processing archive %s',
+                                                  msgid='cache.sync')
                 for archive_id in archive_ids:
                     archive_name = lookup_name(archive_id)
                     if self.progress:
diff --git a/src/borg/helpers.py b/src/borg/helpers.py
index 7f2a4e670..b4efd7e70 100644
--- a/src/borg/helpers.py
+++ b/src/borg/helpers.py
@@ -1384,13 +1384,15 @@ class ProgressIndicatorBase:
 
     @classmethod
     def operation_id(cls):
+        """Unique number, can be used by receiving applications to distinguish different operations."""
         cls.operation_id_counter += 1
         return cls.operation_id_counter
 
-    def __init__(self):
+    def __init__(self, msgid=None):
         self.handler = None
         self.logger = logging.getLogger(self.LOGGER)
         self.id = self.operation_id()
+        self.msgid = msgid
 
         # If there are no handlers, set one up explicitly because the
         # terminator and propagation needs to be set.  If there are,
@@ -1426,12 +1428,13 @@ class ProgressIndicatorBase:
         assert self.json
         if not self.emit:
             return
-        print(json.dumps(dict(
+        kwargs.update(dict(
             operation=self.id,
+            msgid=self.msgid,
             type=self.JSON_TYPE,
-            finished=finished,
-            **kwargs,
-        )), file=sys.stderr)
+            finished=finished
+        ))
+        print(json.dumps(kwargs), file=sys.stderr)
 
     def finish(self):
         if self.json:
@@ -1461,7 +1464,7 @@ class ProgressIndicatorMessage(ProgressIndicatorBase):
 class ProgressIndicatorPercent(ProgressIndicatorBase):
     JSON_TYPE = 'progress_percent'
 
-    def __init__(self, total=0, step=5, start=0, msg="%3.0f%%"):
+    def __init__(self, total=0, step=5, start=0, msg="%3.0f%%", msgid=None):
         """
         Percentage-based progress indicator
 
@@ -1476,7 +1479,7 @@ class ProgressIndicatorPercent(ProgressIndicatorBase):
         self.step = step
         self.msg = msg
 
-        super().__init__()
+        super().__init__(msgid=msgid)
 
     def progress(self, current=None, increase=1):
         if current is not None:
diff --git a/src/borg/repository.py b/src/borg/repository.py
index 81935f4a9..41d865d54 100644
--- a/src/borg/repository.py
+++ b/src/borg/repository.py
@@ -483,7 +483,8 @@ class Repository:
             unused = []
 
         logger.debug('compaction started.')
-        pi = ProgressIndicatorPercent(total=len(self.compact), msg='Compacting segments %3.0f%%', step=1)
+        pi = ProgressIndicatorPercent(total=len(self.compact), msg='Compacting segments %3.0f%%', step=1,
+                                      msgid='repository.compact_segments')
         for segment, freeable_space in sorted(self.compact.items()):
             if not self.io.segment_exists(segment):
                 logger.warning('segment %d not found, but listed in compaction data', segment)
@@ -584,7 +585,8 @@ class Repository:
         self.prepare_txn(index_transaction_id, do_cleanup=False)
         try:
             segment_count = sum(1 for _ in self.io.segment_iterator())
-            pi = ProgressIndicatorPercent(total=segment_count, msg="Replaying segments %3.0f%%")
+            pi = ProgressIndicatorPercent(total=segment_count, msg='Replaying segments %3.0f%%',
+                                          msgid='repository.replay_segments')
             for i, (segment, filename) in enumerate(self.io.segment_iterator()):
                 pi.show(i)
                 if index_transaction_id is not None and segment <= index_transaction_id:
@@ -694,7 +696,8 @@ class Repository:
         self.prepare_txn(None)  # self.index, self.compact, self.segments all empty now!
         segment_count = sum(1 for _ in self.io.segment_iterator())
         logger.debug('Found %d segments', segment_count)
-        pi = ProgressIndicatorPercent(total=segment_count, msg="Checking segments %3.1f%%", step=0.1)
+        pi = ProgressIndicatorPercent(total=segment_count, msg='Checking segments %3.1f%%', step=0.1,
+                                      msgid='repository.check')
         for i, (segment, filename) in enumerate(self.io.segment_iterator()):
             pi.show(i)
             if segment > transaction_id:

From 9f446aa6d434c1b926968d73e3a2dff119aca95b Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Mon, 27 Feb 2017 20:51:20 +0100
Subject: [PATCH 03/10] pass --log-json to remote

Obviously this means that --log-json with remote repos requires 1.1
on the remote end, but if you don't have that, then random "Remote:"
lines would break stderr anyway.
---
 src/borg/logger.py | 2 +-
 src/borg/remote.py | 6 ++++++
 2 files changed, 7 insertions(+), 1 deletion(-)

diff --git a/src/borg/logger.py b/src/borg/logger.py
index 8bf0098c9..6d4a4402d 100644
--- a/src/borg/logger.py
+++ b/src/borg/logger.py
@@ -92,7 +92,7 @@ def setup_logging(stream=None, conf_fname=None, env_var='BORG_LOGGING_CONF', lev
         fmt = '$LOG %(levelname)s %(name)s Remote: %(message)s'
     else:
         fmt = '%(message)s'
-    formatter = JsonFormatter(fmt) if json else logging.Formatter(fmt)
+    formatter = JsonFormatter(fmt) if json and not is_serve else logging.Formatter(fmt)
     handler.setFormatter(formatter)
     borg_logger = logging.getLogger('borg')
     borg_logger.formatter = formatter
diff --git a/src/borg/remote.py b/src/borg/remote.py
index 05ba6c8cb..7bb9ece04 100644
--- a/src/borg/remote.py
+++ b/src/borg/remote.py
@@ -636,6 +636,12 @@ This problem will go away as soon as the server has been upgraded to 1.0.7+.
                 opts.append('--critical')
             else:
                 raise ValueError('log level missing, fix this code')
+            try:
+                borg_logger = logging.getLogger('borg')
+                if borg_logger.json:
+                    opts.append('--log-json')
+            except AttributeError:
+                pass
         env_vars = []
         if yes(env_var_override='BORG_HOSTNAME_IS_UNIQUE', env_msg=None, prompt=False):
             env_vars.append('BORG_HOSTNAME_IS_UNIQUE=yes')

From fcad0ddab41603b9ef28edd948a01a2860f6a76a Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Mon, 27 Feb 2017 21:24:56 +0100
Subject: [PATCH 04/10] pass msgid for common errors

---
 docs/internals/frontends.rst | 41 ++++++++++++++++++++++++++++++++++--
 src/borg/archiver.py         |  9 ++++++--
 src/borg/logger.py           | 16 ++++++++++++++
 3 files changed, 62 insertions(+), 4 deletions(-)

diff --git a/docs/internals/frontends.rst b/docs/internals/frontends.rst
index e11a1a3f4..85b00134d 100644
--- a/docs/internals/frontends.rst
+++ b/docs/internals/frontends.rst
@@ -45,7 +45,7 @@ progress_message
 
     operation
         unique, opaque integer ID of the operation
-    msgid
+    :ref:`msgid <msgid>`
         Message ID of the operation (may be *none*)
     finished
         boolean indicating whether the operation has finished, only the last object for an *operation*
@@ -58,7 +58,7 @@ progress_percent
 
     operation
         unique, opaque integer ID of the operation
-    msgid
+    :ref:`msgid <msgid>`
         Message ID of the operation (may be *none*)
     finished
         boolean indicating whether the operation has finished, only the last object for an *operation*
@@ -90,6 +90,8 @@ log_message
         Name of the emitting entity
     message
         Formatted log message
+    :ref:`msgid <msgid>`
+        Message ID, may be *none* or absent
 
 Standard output
 ---------------
@@ -188,3 +190,38 @@ comment
 Listing the contents of an archive can produce *a lot* of JSON. Each item (file, directory, ...) is described
 by one object in the *files* array of the :ref:`borg_list` output. Refer to the *borg list* documentation for
 the available keys and their meaning.
+
+.. _msgid:
+
+Message IDs
+-----------
+
+Message IDs are strings that essentially give a log message or operation a name, without actually using the
+full text, since texts change more frequently. Message IDs are unambiguous and reduce the need to parse
+log messages.
+
+Assigned message IDs are:
+
+.. note::
+
+    This list is incomplete.
+
+Errors
+    - Archive.AlreadyExists
+    - Archive.DoesNotExist
+    - Archive.IncompatibleFilesystemEncodingError
+    - IntegrityError
+    - NoManifestError
+    - PlaceholderError
+
+Operations
+    - cache.begin_transaction
+    - cache.commit
+    - cache.sync
+    - repository.compact_segments
+    - repository.replay_segments
+    - repository.check_segments
+    - check.verify_data
+    - extract
+    - extract.permissions
+    - archive.delete
diff --git a/src/borg/archiver.py b/src/borg/archiver.py
index ad8a286d8..88fe23287 100644
--- a/src/borg/archiver.py
+++ b/src/borg/archiver.py
@@ -3287,7 +3287,7 @@ def main():  # pragma: no cover
          signal_handler('SIGUSR2', sig_trace_handler), \
          signal_handler('SIGINFO', sig_info_handler):
         archiver = Archiver()
-        msg = tb = None
+        msg = msgid = tb = None
         tb_log_level = logging.ERROR
         try:
             args = archiver.get_args(sys.argv, os.environ.get('SSH_ORIGINAL_COMMAND'))
@@ -3304,11 +3304,13 @@ def main():  # pragma: no cover
             exit_code = archiver.run(args)
         except Error as e:
             msg = e.get_message()
+            msgid = type(e).__qualname__
             tb_log_level = logging.ERROR if e.traceback else logging.DEBUG
             tb = "%s\n%s" % (traceback.format_exc(), sysinfo())
             exit_code = e.exit_code
         except RemoteRepository.RPCError as e:
             important = e.exception_class not in ('LockTimeout', )
+            msgid = e.exception_class
             tb_log_level = logging.ERROR if important else logging.DEBUG
             if important:
                 msg = e.exception_full
@@ -3319,6 +3321,7 @@ def main():  # pragma: no cover
             exit_code = EXIT_ERROR
         except Exception:
             msg = 'Local Exception'
+            msgid = 'Exception'
             tb_log_level = logging.ERROR
             tb = '%s\n%s' % (traceback.format_exc(), sysinfo())
             exit_code = EXIT_ERROR
@@ -3329,14 +3332,16 @@ def main():  # pragma: no cover
             exit_code = EXIT_ERROR
         except SigTerm:
             msg = 'Received SIGTERM'
+            msgid = 'Signal.SIGTERM'
             tb_log_level = logging.DEBUG
             tb = '%s\n%s' % (traceback.format_exc(), sysinfo())
             exit_code = EXIT_ERROR
         except SigHup:
             msg = 'Received SIGHUP.'
+            msgid = 'Signal.SIGHUP'
             exit_code = EXIT_ERROR
         if msg:
-            logger.error(msg)
+            logger.error(msg, msgid=msgid)
         if tb:
             logger.log(tb_log_level, tb)
         if args.show_rc:
diff --git a/src/borg/logger.py b/src/borg/logger.py
index 6d4a4402d..672c1e897 100644
--- a/src/borg/logger.py
+++ b/src/borg/logger.py
@@ -165,24 +165,38 @@ def create_logger(name=None):
             return self.__logger.setLevel(*args, **kw)
 
         def log(self, *args, **kw):
+            if 'msgid' in kw:
+                kw.setdefault('extra', {})['msgid'] = kw.pop('msgid')
             return self.__logger.log(*args, **kw)
 
         def exception(self, *args, **kw):
+            if 'msgid' in kw:
+                kw.setdefault('extra', {})['msgid'] = kw.pop('msgid')
             return self.__logger.exception(*args, **kw)
 
         def debug(self, *args, **kw):
+            if 'msgid' in kw:
+                kw.setdefault('extra', {})['msgid'] = kw.pop('msgid')
             return self.__logger.debug(*args, **kw)
 
         def info(self, *args, **kw):
+            if 'msgid' in kw:
+                kw.setdefault('extra', {})['msgid'] = kw.pop('msgid')
             return self.__logger.info(*args, **kw)
 
         def warning(self, *args, **kw):
+            if 'msgid' in kw:
+                kw.setdefault('extra', {})['msgid'] = kw.pop('msgid')
             return self.__logger.warning(*args, **kw)
 
         def error(self, *args, **kw):
+            if 'msgid' in kw:
+                kw.setdefault('extra', {})['msgid'] = kw.pop('msgid')
             return self.__logger.error(*args, **kw)
 
         def critical(self, *args, **kw):
+            if 'msgid' in kw:
+                kw.setdefault('extra', {})['msgid'] = kw.pop('msgid')
             return self.__logger.critical(*args, **kw)
 
     return LazyLogger(name)
@@ -194,6 +208,8 @@ class JsonFormatter(logging.Formatter):
         'levelname',
         'name',
         'message',
+        # msgid is an attribute we made up in Borg to expose a non-changing handle for log messages
+        'msgid',
     )
 
     # Other attributes that are not very useful but do exist:

From d3271096048afcfefd1afcc28bbbc597e74ab57b Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Mon, 27 Feb 2017 22:36:09 +0100
Subject: [PATCH 05/10] json progress: emit info (current $something)

---
 docs/internals/frontends.rst | 9 ++++++++-
 src/borg/helpers.py          | 6 +++---
 2 files changed, 11 insertions(+), 4 deletions(-)

diff --git a/docs/internals/frontends.rst b/docs/internals/frontends.rst
index 85b00134d..66ea85843 100644
--- a/docs/internals/frontends.rst
+++ b/docs/internals/frontends.rst
@@ -22,7 +22,8 @@ where each line is a JSON object. The *type* key of the object determines its ot
 
 Since JSON can only encode text, any string representing a file system path may miss non-text parts.
 
-The following types are in use:
+The following types are in use. Progress information is governed by the usual rules for progress information,
+it is not produced unless ``--progress`` is specified.
 
 archive_progress
     Output during operations creating archives (:ref:`borg_create` and :ref:`borg_recreate`).
@@ -67,6 +68,8 @@ progress_percent
         A formatted progress message, this will include the percentage and perhaps other information
     current
         Current value (always less-or-equal to *total*)
+    info
+        Array that describes the current item, may be *none*, contents depend on *msgid*
     total
         Total value
 
@@ -218,10 +221,14 @@ Operations
     - cache.begin_transaction
     - cache.commit
     - cache.sync
+
+      *info* is one string element, the name of the archive currently synced.
     - repository.compact_segments
     - repository.replay_segments
     - repository.check_segments
     - check.verify_data
     - extract
+
+      *info* is one string element, the name of the path currently extracted.
     - extract.permissions
     - archive.delete
diff --git a/src/borg/helpers.py b/src/borg/helpers.py
index b4efd7e70..da6ef776e 100644
--- a/src/borg/helpers.py
+++ b/src/borg/helpers.py
@@ -1508,13 +1508,13 @@ class ProgressIndicatorPercent(ProgressIndicatorBase):
                     if terminal_space != -1:
                         space = terminal_space - len(self.msg % tuple([pct] + info[:-1] + ['']))
                         info[-1] = ellipsis_truncate(info[-1], space)
-                return self.output(self.msg % tuple([pct] + info), justify=False)
+                return self.output(self.msg % tuple([pct] + info), justify=False, info=info)
 
             return self.output(self.msg % pct)
 
-    def output(self, message, justify=True):
+    def output(self, message, justify=True, info=None):
         if self.json:
-            self.output_json(message=message, current=self.counter, total=self.total)
+            self.output_json(message=message, current=self.counter, total=self.total, info=info)
         else:
             if justify:
                 message = justify_to_terminal_size(message)

From 51350953b05c4056c3e1b5f197c04bfefa8b4001 Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Mon, 27 Feb 2017 22:54:01 +0100
Subject: [PATCH 06/10] json: examples

---
 docs/internals/frontends.rst | 130 ++++++++++++++++++++++++++++++++++-
 1 file changed, 129 insertions(+), 1 deletion(-)

diff --git a/docs/internals/frontends.rst b/docs/internals/frontends.rst
index 66ea85843..358f30faa 100644
--- a/docs/internals/frontends.rst
+++ b/docs/internals/frontends.rst
@@ -1,5 +1,5 @@
 .. include:: ../global.rst.inc
-.. highlight:: none
+.. highlight:: json
 
 .. _json_output:
 
@@ -141,6 +141,31 @@ stats
     unique_csize
         Compressed and encrypted size of all chunks
 
+Example *borg info* output::
+
+    {
+        "cache": {
+            "path": "/home/user/.cache/borg/0cbe6166b46627fd26b97f8831e2ca97584280a46714ef84d2b668daf8271a23",
+            "stats": {
+                "total_chunks": 511533,
+                "total_csize": 17948017540,
+                "total_size": 22635749792,
+                "total_unique_chunks": 54892,
+                "unique_csize": 1920405405,
+                "unique_size": 2449675468
+            }
+        },
+        "encryption": {
+            "mode": "repokey"
+        },
+        "repository": {
+            "id": "0cbe6166b46627fd26b97f8831e2ca97584280a46714ef84d2b668daf8271a23",
+            "last_modified": "Mon, 2017-02-27 21:21:58",
+            "location": "/home/user/testrepo"
+        },
+        "security_dir": "/home/user/.config/borg/security/0cbe6166b46627fd26b97f8831e2ca97584280a46714ef84d2b668daf8271a23"
+    }
+
 .. rubric:: Archive formats
 
 :ref:`borg_info` uses an extended format for archives, which is more expensive to retrieve, while
@@ -188,12 +213,115 @@ username
 comment
     Archive comment, if any
 
+Example of a simple archive listing (``borg list --last 1 --json``)::
+
+    {
+        "archives": [
+            {
+                "archive": "2017-02-27T21:21:51",
+                "barchive": "2017-02-27T21:21:51",
+                "id": "80cd07219ad725b3c5f665c1dcf119435c4dee1647a560ecac30f8d40221a46a",
+                "name": "2017-02-27T21:21:51",
+                "time": "Mon, 2017-02-27 21:21:52"
+            }
+        ],
+        "encryption": {
+            "mode": "repokey"
+        },
+        "repository": {
+            "id": "0cbe6166b46627fd26b97f8831e2ca97584280a46714ef84d2b668daf8271a23",
+            "last_modified": "Mon, 2017-02-27 21:21:58",
+            "location": "/home/user/repository"
+        }
+    }
+
+The same archive with more information (``borg info --last 1 --json``)::
+
+    {
+        "archives": [
+            {
+                "command_line": [
+                    "/home/user/.local/bin/borg",
+                    "create",
+                    "/home/user/repository",
+                    "..."
+                ],
+                "comment": "",
+                "duration": 5.641542,
+                "end": "Mon, 2017-02-27 21:21:58",
+                "hostname": "host",
+                "id": "80cd07219ad725b3c5f665c1dcf119435c4dee1647a560ecac30f8d40221a46a",
+                "limits": {
+                    "max_archive_size": 0.0001330855110409714
+                },
+                "name": "2017-02-27T21:21:51",
+                "start": "Mon, 2017-02-27 21:21:52",
+                "stats": {
+                    "compressed_size": 1880961894,
+                    "deduplicated_size": 2791,
+                    "nfiles": 53669,
+                    "original_size": 2400471280
+                },
+                "username": "user"
+            }
+        ],
+        "cache": {
+            "path": "/home/user/.cache/borg/0cbe6166b46627fd26b97f8831e2ca97584280a46714ef84d2b668daf8271a23",
+            "stats": {
+                "total_chunks": 511533,
+                "total_csize": 17948017540,
+                "total_size": 22635749792,
+                "total_unique_chunks": 54892,
+                "unique_csize": 1920405405,
+                "unique_size": 2449675468
+            }
+        },
+        "encryption": {
+            "mode": "repokey"
+        },
+        "repository": {
+            "id": "0cbe6166b46627fd26b97f8831e2ca97584280a46714ef84d2b668daf8271a23",
+            "last_modified": "Mon, 2017-02-27 21:21:58",
+            "location": "/home/user/repository"
+        }
+    }
+
 .. rubric:: File listings
 
 Listing the contents of an archive can produce *a lot* of JSON. Each item (file, directory, ...) is described
 by one object in the *files* array of the :ref:`borg_list` output. Refer to the *borg list* documentation for
 the available keys and their meaning.
 
+Example (excerpt)::
+
+    {
+        "encryption": {
+            "mode": "repokey"
+        },
+        "repository": {
+            "id": "0cbe6166b46627fd26b97f8831e2ca97584280a46714ef84d2b668daf8271a23",
+            "last_modified": "Mon, 2017-02-27 21:21:58",
+            "location": "/home/user/repository"
+        },
+        "files": [
+            {
+                "type": "d",
+                "mode": "drwxr-xr-x",
+                "user": "user",
+                "group": "user",
+                "uid": 1000,
+                "gid": 1000,
+                "path": "linux",
+                "healthy": true,
+                "source": "",
+                "linktarget": "",
+                "flags": null,
+                "isomtime": "Sat, 2016-05-07 19:46:01",
+                "size": 0
+            }
+        ]
+    }
+
 .. _msgid:
 
 Message IDs

From 8e1edaf258b96b94a36408ba816e1831be3c75fe Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Tue, 28 Feb 2017 01:30:11 +0100
Subject: [PATCH 07/10] ArchiveFormatter: add "start" key for compatibility
 with "info"

---
 docs/internals/frontends.rst | 10 +++++-----
 src/borg/helpers.py          |  1 +
 2 files changed, 6 insertions(+), 5 deletions(-)

diff --git a/docs/internals/frontends.rst b/docs/internals/frontends.rst
index 358f30faa..6409ce6f9 100644
--- a/docs/internals/frontends.rst
+++ b/docs/internals/frontends.rst
@@ -173,12 +173,11 @@ Example *borg info* output::
 array under the *archives* key, while :ref:`borg_create` returns a single archive object under the
 *archive* key.
 
-Both formats contain a *name* key with the archive name, and the *id* key with the hexadecimal archive ID.
+Both formats contain a *name* key with the archive name, the *id* key with the hexadecimal archive ID,
+and the *start* key with the start timestamp.
 
- info and create further have:
+info and create further have:
 
-start
-    Start timestamp
 end
     End timestamp
 duration
@@ -222,7 +221,8 @@ Example of a simple archive listing (``borg list --last 1 --json``)::
                 "barchive": "2017-02-27T21:21:51",
                 "id": "80cd07219ad725b3c5f665c1dcf119435c4dee1647a560ecac30f8d40221a46a",
                 "name": "2017-02-27T21:21:51",
-                "time": "Mon, 2017-02-27 21:21:52"
+                "time": "Mon, 2017-02-27 21:21:52",
+                "start": "Mon, 2017-02-27 21:21:52"
             }
         ],
         "encryption": {
diff --git a/src/borg/helpers.py b/src/borg/helpers.py
index da6ef776e..9f5de739d 100644
--- a/src/borg/helpers.py
+++ b/src/borg/helpers.py
@@ -1622,6 +1622,7 @@ class ArchiveFormatter(BaseFormatter):
             'archive': remove_surrogates(archive.name),
             'id': bin_to_hex(archive.id),
             'time': format_time(to_localtime(archive.ts)),
+            'start': format_time(to_localtime(archive.ts)),
         }
 
     @staticmethod

From 6ee0585b337ee63dab345cc42ad9abe1e75dced3 Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Tue, 28 Feb 2017 02:04:46 +0100
Subject: [PATCH 08/10] extract: fix missing call to ProgressIndicator.finish

---
 src/borg/archiver.py | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/src/borg/archiver.py b/src/borg/archiver.py
index 88fe23287..c1a778a2d 100644
--- a/src/borg/archiver.py
+++ b/src/borg/archiver.py
@@ -588,6 +588,9 @@ class Archiver:
             except BackupOSError as e:
                 self.print_warning('%s: %s', remove_surrogates(orig_path), e)
 
+        if pi:
+            pi.finish()
+
         if not args.dry_run:
             pi = ProgressIndicatorPercent(total=len(dirs), msg='Setting directory permissions %3.0f%%',
                                           msgid='extract.permissions')

From 7cce650a38b1a3064c6baf1cb92dd778071dfffc Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Tue, 28 Feb 2017 11:58:43 +0100
Subject: [PATCH 09/10] json docs: rather complete error list

---
 docs/internals/frontends.rst | 122 ++++++++++++++++++++++++++++++++---
 scripts/errorlist.py         |  14 ++++
 2 files changed, 127 insertions(+), 9 deletions(-)
 create mode 100755 scripts/errorlist.py

diff --git a/docs/internals/frontends.rst b/docs/internals/frontends.rst
index 6409ce6f9..0553cd000 100644
--- a/docs/internals/frontends.rst
+++ b/docs/internals/frontends.rst
@@ -96,6 +96,39 @@ log_message
     :ref:`msgid <msgid>`
         Message ID, may be *none* or absent
 
+.. rubric:: Examples (reformatted, each object would be on exactly one line)
+
+:ref:`borg_extract` progress::
+
+    {"message": "100.0% Extracting: src/borgbackup.egg-info/entry_points.txt",
+     "current": 13000228, "total": 13004993, "info": ["src/borgbackup.egg-info/entry_points.txt"],
+     "operation": 1, "msgid": "extract", "type": "progress_percent", "finished": false}
+    {"message": "100.0% Extracting: src/borgbackup.egg-info/SOURCES.txt",
+     "current": 13004993, "total": 13004993, "info": ["src/borgbackup.egg-info/SOURCES.txt"],
+     "operation": 1, "msgid": "extract", "type": "progress_percent", "finished": false}
+    {"operation": 1, "msgid": "extract", "type": "progress_percent", "finished": true}
+
+:ref:`borg_create` file listing with progress::
+
+    {"original_size": 0, "compressed_size": 0, "deduplicated_size": 0, "nfiles": 0, "type": "archive_progress", "path": "src"}
+    {"type": "file_status", "status": "U", "path": "src/borgbackup.egg-info/entry_points.txt"}
+    {"type": "file_status", "status": "U", "path": "src/borgbackup.egg-info/SOURCES.txt"}
+    {"type": "file_status", "status": "d", "path": "src/borgbackup.egg-info"}
+    {"type": "file_status", "status": "d", "path": "src"}
+    {"original_size": 13176040, "compressed_size": 11386863, "deduplicated_size": 503, "nfiles": 277, "type": "archive_progress", "path": ""}
+
+Internal transaction progress::
+
+    {"message": "Saving files cache", "operation": 2, "msgid": "cache.commit", "type": "progress_message", "finished": false}
+    {"message": "Saving cache config", "operation": 2, "msgid": "cache.commit", "type": "progress_message", "finished": false}
+    {"message": "Saving chunks cache", "operation": 2, "msgid": "cache.commit", "type": "progress_message", "finished": false}
+    {"operation": 2, "msgid": "cache.commit", "type": "progress_message", "finished": true}
+
+A debug log message::
+
+    {"message": "35 self tests completed in 0.08 seconds",
+     "type": "log_message", "created": 1488278449.5575905, "levelname": "DEBUG", "name": "borg.archiver"}
+
 Standard output
 ---------------
 
@@ -333,17 +366,88 @@ log messages.
 
 Assigned message IDs are:
 
-.. note::
-
-    This list is incomplete.
+.. See scripts/errorlist.py; this is slightly edited.
 
 Errors
-    - Archive.AlreadyExists
-    - Archive.DoesNotExist
-    - Archive.IncompatibleFilesystemEncodingError
-    - IntegrityError
-    - NoManifestError
-    - PlaceholderError
+    Archive.AlreadyExists
+        Archive {} already exists
+    Archive.DoesNotExist
+        Archive {} does not exist
+    Archive.IncompatibleFilesystemEncodingError
+        Failed to encode filename "{}" into file system encoding "{}". Consider configuring the LANG environment variable.
+    Cache.CacheInitAbortedError
+        Cache initialization aborted
+    Cache.EncryptionMethodMismatch
+        Repository encryption method changed since last access, refusing to continue
+    Cache.RepositoryAccessAborted
+        Repository access aborted
+    Cache.RepositoryIDNotUnique
+        Cache is newer than repository - do you have multiple, independently updated repos with same ID?
+    Cache.RepositoryReplay
+        Cache is newer than repository - this is either an attack or unsafe (multiple repos with same ID)
+    Buffer.MemoryLimitExceeded
+        Requested buffer size {} is above the limit of {}.
+    ExtensionModuleError
+        The Borg binary extension modules do not seem to be properly installed
+    IntegrityError
+        Data integrity error: {}
+    NoManifestError
+        Repository has no manifest.
+    PlaceholderError
+        Formatting Error: "{}".format({}): {}({})
+    KeyfileInvalidError
+        Invalid key file for repository {} found in {}.
+    KeyfileMismatchError
+        Mismatch between repository {} and key file {}.
+    KeyfileNotFoundError
+        No key file for repository {} found in {}.
+    PassphraseWrong
+        passphrase supplied in BORG_PASSPHRASE is incorrect
+    PasswordRetriesExceeded
+        exceeded the maximum password retries
+    RepoKeyNotFoundError
+        No key entry found in the config of repository {}.
+    UnsupportedManifestError
+        Unsupported manifest envelope. A newer version is required to access this repository.
+    UnsupportedPayloadError
+        Unsupported payload type {}. A newer version is required to access this repository.
+    NotABorgKeyFile
+        This file is not a borg key backup, aborting.
+    RepoIdMismatch
+        This key backup seems to be for a different backup repository, aborting.
+    UnencryptedRepo
+        Keymanagement not available for unencrypted repositories.
+    UnknownKeyType
+        Keytype {0} is unknown.
+    LockError
+        Failed to acquire the lock {}.
+    LockErrorT
+        Failed to acquire the lock {}.
+    ConnectionClosed
+        Connection closed by remote host
+    InvalidRPCMethod
+        RPC method {} is not valid
+    PathNotAllowed
+        Repository path not allowed
+    RemoteRepository.RPCServerOutdated
+        Borg server is too old for {}. Required version {}
+    UnexpectedRPCDataFormatFromClient
+        Borg {}: Got unexpected RPC data format from client.
+    UnexpectedRPCDataFormatFromServer
+        Got unexpected RPC data format from server:
+        {}
+    Repository.AlreadyExists
+        Repository {} already exists.
+    Repository.CheckNeeded
+        Inconsistency detected. Please run "borg check {}".
+    Repository.DoesNotExist
+        Repository {} does not exist.
+    Repository.InsufficientFreeSpaceError
+        Insufficient free space to complete transaction (required: {}, available: {}).
+    Repository.InvalidRepository
+        {} is not a valid repository. Check repo config.
+    Repository.ObjectNotFound
+        Object with key {} not found in repository {}.
 
 Operations
     - cache.begin_transaction
diff --git a/scripts/errorlist.py b/scripts/errorlist.py
new file mode 100755
index 000000000..bd33faf44
--- /dev/null
+++ b/scripts/errorlist.py
@@ -0,0 +1,14 @@
+#!/usr/bin/env python3
+
+from textwrap import indent
+
+import borg.archiver
+from borg.helpers import Error, ErrorWithTraceback
+
+classes = Error.__subclasses__() + ErrorWithTraceback.__subclasses__()
+
+for cls in sorted(classes, key=lambda cls: (cls.__module__, cls.__qualname__)):
+    if cls is ErrorWithTraceback:
+        continue
+    print('   ', cls.__qualname__)
+    print(indent(cls.__doc__, ' ' * 8))

From abb0a20d4f2539e25a0277b7a1c6bc2426888fc1 Mon Sep 17 00:00:00 2001
From: Marian Beermann <public@enkore.de>
Date: Wed, 1 Mar 2017 16:58:06 +0100
Subject: [PATCH 10/10] list: files->items, clarifications

---
 docs/internals/frontends.rst   | 15 ++++++---------
 src/borg/helpers.py            |  4 +++-
 src/borg/testsuite/archiver.py | 12 ++++++------
 3 files changed, 15 insertions(+), 16 deletions(-)

diff --git a/docs/internals/frontends.rst b/docs/internals/frontends.rst
index 0553cd000..df6d50329 100644
--- a/docs/internals/frontends.rst
+++ b/docs/internals/frontends.rst
@@ -42,7 +42,7 @@ archive_progress
 
 progress_message
     A message-based progress information with no concrete progress information, just a message
-    saying what is currently worked on.
+    saying what is currently being worked on.
 
     operation
         unique, opaque integer ID of the operation
@@ -209,7 +209,7 @@ array under the *archives* key, while :ref:`borg_create` returns a single archiv
 Both formats contain a *name* key with the archive name, the *id* key with the hexadecimal archive ID,
 and the *start* key with the start timestamp.
 
-info and create further have:
+*borg info* and *borg create* further have:
 
 end
     End timestamp
@@ -250,11 +250,8 @@ Example of a simple archive listing (``borg list --last 1 --json``)::
     {
         "archives": [
             {
-                "archive": "2017-02-27T21:21:51",
-                "barchive": "2017-02-27T21:21:51",
                 "id": "80cd07219ad725b3c5f665c1dcf119435c4dee1647a560ecac30f8d40221a46a",
-                "name": "2017-02-27T21:21:51",
-                "time": "Mon, 2017-02-27 21:21:52",
+                "name": "host-system-backup-2017-02-27",
                 "start": "Mon, 2017-02-27 21:21:52"
             }
         ],
@@ -287,7 +284,7 @@ The same archive with more information (``borg info --last 1 --json``)::
                 "limits": {
                     "max_archive_size": 0.0001330855110409714
                 },
-                "name": "2017-02-27T21:21:51",
+                "name": "host-system-backup-2017-02-27",
                 "start": "Mon, 2017-02-27 21:21:52",
                 "stats": {
                     "compressed_size": 1880961894,
@@ -322,7 +319,7 @@ The same archive with more information (``borg info --last 1 --json``)::
 .. rubric:: File listings
 
 Listing the contents of an archive can produce *a lot* of JSON. Each item (file, directory, ...) is described
-by one object in the *files* array of the :ref:`borg_list` output. Refer to the *borg list* documentation for
+by one object in the *items* array of the :ref:`borg_list` output. Refer to the *borg list* documentation for
 the available keys and their meaning.
 
 Example (excerpt)::
@@ -336,7 +333,7 @@ Example (excerpt)::
             "last_modified": "Mon, 2017-02-27 21:21:58",
             "location": "/home/user/repository"
         },
-        "files": [
+        "items": [
             {
                 "type": "d",
                 "mode": "drwxr-xr-x",
diff --git a/src/borg/helpers.py b/src/borg/helpers.py
index 9f5de739d..db9fc92db 100644
--- a/src/borg/helpers.py
+++ b/src/borg/helpers.py
@@ -1617,11 +1617,13 @@ class ArchiveFormatter(BaseFormatter):
 
     def get_item_data(self, archive):
         return {
+            # *name* is the key used by borg-info for the archive name, this makes the formats more compatible
             'name': remove_surrogates(archive.name),
             'barchive': archive.name,
             'archive': remove_surrogates(archive.name),
             'id': bin_to_hex(archive.id),
             'time': format_time(to_localtime(archive.ts)),
+            # *start* is the key used by borg-info for this timestamp, this makes the formats more compatible
             'start': format_time(to_localtime(archive.ts)),
         }
 
@@ -1726,7 +1728,7 @@ class ItemFormatter(BaseFormatter):
         begin = json_dump(basic_json_data(self.archive.manifest))
         begin, _, _ = begin.rpartition('\n}')  # remove last closing brace, we want to extend the object
         begin += ',\n'
-        begin += '    "files": [\n'
+        begin += '    "items": [\n'
         return begin
 
     def end(self):
diff --git a/src/borg/testsuite/archiver.py b/src/borg/testsuite/archiver.py
index 6793e0de9..b59b2cb50 100644
--- a/src/borg/testsuite/archiver.py
+++ b/src/borg/testsuite/archiver.py
@@ -1535,17 +1535,17 @@ class ArchiverTestCase(ArchiverTestCaseBase):
 
         list_archive = json.loads(self.cmd('list', '--json', self.repository_location + '::test'))
         assert list_repo['repository'] == list_archive['repository']
-        files = list_archive['files']
-        assert len(files) == 2
-        file1 = files[1]
+        items = list_archive['items']
+        assert len(items) == 2
+        file1 = items[1]
         assert file1['path'] == 'input/file1'
         assert file1['size'] == 81920
 
         list_archive = json.loads(self.cmd('list', '--json', '--format={sha256}', self.repository_location + '::test'))
         assert list_repo['repository'] == list_archive['repository']
-        files = list_archive['files']
-        assert len(files) == 2
-        file1 = files[1]
+        items = list_archive['items']
+        assert len(items) == 2
+        file1 = items[1]
         assert file1['path'] == 'input/file1'
         assert file1['sha256'] == 'b2915eb69f260d8d3c25249195f2c8f4f716ea82ec760ae929732c0262442b2b'