diff --git a/docs/changes.rst b/docs/changes.rst index 4e9f599897..a5beef2c56 100644 --- a/docs/changes.rst +++ b/docs/changes.rst @@ -197,6 +197,12 @@ New features: - mount: support Windows using WinFsp (via mfusepy), #2316 - import-tar --strip-components: strip leading path components, #6461 - add the BORG_NEW_PASSCOMMAND and BORG_NEW_PASSPHRASE_FD env vars +- extract/export-tar --list --log-json: output a file_status JSON object per listed item, + like create does. The text listing of export-tar has the same "+" prefix as extract's now. + prune/delete/undelete --list --log-json: output an archive_status JSON object per listed + archive, #9454. +- create/recreate --dry-run --progress: show the progress (also as archive_progress JSON + objects with --log-json), it showed nothing Fixes: @@ -247,6 +253,14 @@ Fixes: - locking: try at least once before a lock acquire times out, also with --lock-wait 0 - repoobj: catch get() errors in --find-lost-archives, #10318 +- recreate/transfer --log-json --progress: output archive_progress JSON objects (as + documented), not text progress lines +- import-tar/recreate: count the items by their status, like create does. The counts + were always 0: "Added files" of import-tar --stats, files_stats in the JSON output. +- --log-json: the final archive_progress object (finished: true) has the final statistics. + The progress output is rate limited, so a frontend could not know what was processed + after the previous object (or at all, for a short operation), see also #6570. + Other changes: - update pyinstaller to 6.22.3 @@ -274,6 +288,12 @@ Other changes: but was never really used) - security: drop the manifest timestamp replay check (not needed anymore) - debug get-obj, put-obj, delete-obj: need the key now (to access the chunk index) +- cockpit: process borg's --log-json output (progress, file list, log messages, prompts) + instead of parsing text lines, #9454. The display depends on the command: archive + statistics for create/import-tar/recreate/transfer (with the final statistics from + --json), a progress bar for extract/export-tar, the progress phases for the other + commands. Yes/no prompts are shown as a dialog. The cockpit exits with the exit code + of the borg command. - docs: - extract: document the metadata that can only be restored as root, #8088 @@ -283,6 +303,7 @@ Other changes: - derive the borg passphrase from a YubiKey (challenge-response), #4549 - protect the borg passphrase with age (which also supports crypto tokens, TPM, Apple Secure Enclave, ... via age plugins), #4549 + - add a usage page for the cockpit TUI, #9454 - tests: - add an archiver-level test for BORG_WORKAROUNDS=authenticated_no_key diff --git a/docs/installation.rst b/docs/installation.rst index 91132393fb..9da01eec6f 100644 --- a/docs/installation.rst +++ b/docs/installation.rst @@ -193,7 +193,7 @@ development header files (sometimes in a separate `-dev` or `-devel` package). - borgstore[rest,blake3,sftp] ~= 0.7.0 (use `pip install borgbackup[sftp]`) * Optionally, if you wish to use rclone Backend: - borgstore[rest,blake3,rclone] ~= 0.7.0 (use `pip install borgbackup[rclone]`) -* Optionally, if you wish to use the TUI (``borg --cockpit``): +* Optionally, if you wish to use the cockpit TUI (``borg --cockpit``, see :ref:`cockpit`): - textual >= 6.8.0 (use `pip install borgbackup[cockpit]`) If you have troubles finding the right package names, have a look at the diff --git a/docs/internals/frontends.rst b/docs/internals/frontends.rst index ad0f45a2e5..5eae2b4759 100644 --- a/docs/internals/frontends.rst +++ b/docs/internals/frontends.rst @@ -90,13 +90,15 @@ it is not produced unless ``--progress`` is specified. archive_progress Output during operations creating archives (:ref:`borg_create`, :ref:`borg_import-tar`, :ref:`borg_recreate` and :ref:`borg_transfer`). - The following keys exist, each represents the current progress. + The following keys exist, each represents the current progress. The output is rate limited, so + only the last object (*finished* is *true*) tells about everything that was processed. original_size Original size of the data processed so far (before compression and deduplication) deduplicated_size Deduplicated size of the data processed so far (before compression): the size of the - chunks that were new to the repository + chunks that were new to the repository. Absent for a ``--dry-run`` of :ref:`borg_create` + or :ref:`borg_recreate`: it only knows the number of files and the original size. nfiles Number of (regular) files processed so far hashing_time @@ -105,7 +107,8 @@ archive_progress Seconds spent chunking file contents so far (float) files_stats Object mapping the single-character file status (as used by ``--list``) to the number of - files that got that status so far, e.g. ``{"A": 3, "d": 3}`` + items that got that status so far, e.g. ``{"A": 3, "d": 3}``. It is empty for + :ref:`borg_transfer`, which has no file status. store_stats Object with the storage backend statistics. It is empty here, it is only filled in for the final :ref:`borg_create` ``--json`` output on *stdout*, see `Archive formats`_. @@ -115,8 +118,8 @@ archive_progress Unix timestamp (float) finished boolean indicating whether the operation has finished, only the last object for an *operation* - can have this property set to *true*. That last object has no keys besides *time*, *type* - and *finished*. + can have this property set to *true*. That last object has the final statistics of the + archive and no *path*. progress_message A message-based progress information with no concrete progress information, just a message @@ -158,15 +161,49 @@ progress_percent Unix timestamp (float) file_status - This is only output by :ref:`borg_create`, :ref:`borg_import-tar` and :ref:`borg_recreate` if - ``--list`` is specified. The usual rules for the file listing applies, including the - ``--filter`` option. + One object per listed item, output by :ref:`borg_create`, :ref:`borg_import-tar`, + :ref:`borg_recreate`, :ref:`borg_extract` and :ref:`borg_export-tar` if ``--list`` is + specified. The usual rules for the file listing apply, including the ``--filter`` option. status - Single-character status as for regular list output + Single-character status as for regular list output: the item flags of :ref:`borg_create`, + or ``+`` (item extracted / exported) and ``-`` (item excluded) for :ref:`borg_extract` + and :ref:`borg_export-tar`. path Path of the file system object +archive_status + One object per listed archive, output by :ref:`borg_prune` (``--list``, ``--list-kept`` and + ``--list-pruned``), :ref:`borg_delete` and :ref:`borg_undelete` (``--list``). With ``--json``, + :ref:`borg_prune` outputs the archives on *stdout* instead. + + status + *kept* or *pruned* (:ref:`borg_prune`), *deleted* (:ref:`borg_delete`) or *undeleted* + (:ref:`borg_undelete`). With ``--dry-run``, this is what would be done. + dry_run + *true* for a ``--dry-run``: *status* tells what would be done, nothing was changed + name, archive + Name of the archive + id + Archive ID (hex) + time + Archive timestamp + message + The text line of the ``--list`` output, e.g. *Keeping archive (rule: daily #1): ...* + + :ref:`borg_prune` additionally gives the keys of the archive objects of ``borg prune --json``: + the keys requested via ``--format`` and + + group + Object mapping the ``--group-by`` keys to the values of this archive + kept + *true* if the archive is kept, *false* if it is pruned + keep_rule, kept_oldest, kept_archive_number + For a kept archive: the rule keeping it (e.g. *daily*), whether it is the oldest archive kept + by the rule, and its number within the rule (1 = the most recent one) + deleted_archive_number + For a pruned archive: its number among the pruned archives (1 = the first one pruned) + log_message Any regular log output invokes this type. Regular log options and filtering applies to these as well. @@ -208,7 +245,35 @@ See Prompts_ for the types used by prompts. {"type": "file_status", "status": "A", "path": "src/linux/file1"} {"type": "file_status", "status": "d", "path": "src/linux"} {"type": "file_status", "status": "d", "path": "src"} - {"time": 1787900398.686938, "type": "archive_progress", "finished": true} + {"original_size": 250012, "deduplicated_size": 250012, "nfiles": 3, "hashing_time": 0.002, + "chunking_time": 0.001, "files_stats": {"A": 3, "d": 3}, "store_stats": {}, "time": 1787900398.686938, + "type": "archive_progress", "finished": true} + +:ref:`borg_extract` file listing, with ``--exclude src/linux/baz/file3``:: + + {"type": "file_status", "status": "+", "path": "src"} + {"type": "file_status", "status": "+", "path": "src/linux"} + {"type": "file_status", "status": "+", "path": "src/linux/baz"} + {"type": "file_status", "status": "+", "path": "src/linux/baz/file2"} + {"type": "file_status", "status": "-", "path": "src/linux/baz/file3"} + {"type": "file_status", "status": "+", "path": "src/linux/file1"} + +:ref:`borg_prune` archive listing, with ``--list --dry-run --keep-daily=1``:: + + {"name": "daily", "archive": "daily", "id": "2c77c68a...", "time": "2026-09-09T02:00:00.000000+02:00", + "group": {"name": "daily", "host": "host"}, "kept": true, "keep_rule": "daily", "kept_oldest": false, + "kept_archive_number": 1, "status": "kept", "dry_run": true, "type": "archive_status", + "message": "Keeping archive (rule: daily #1): daily Wed, 2026-09-09 02:00:00 +0200 [2c77c68a...]"} + {"name": "daily", "archive": "daily", "id": "99a5671a...", "time": "2026-09-08T02:00:00.000000+02:00", + "group": {"name": "daily", "host": "host"}, "kept": false, "deleted_archive_number": 1, "status": "pruned", + "dry_run": true, "type": "archive_status", + "message": "Would prune: daily Tue, 2026-09-08 02:00:00 +0200 [99a5671a...]"} + +:ref:`borg_delete` archive listing, with ``--list``:: + + {"name": "daily", "archive": "daily", "id": "99a5671a...", "time": "2026-09-08T02:00:00.000000+02:00", + "status": "deleted", "dry_run": false, "type": "archive_status", + "message": "Deleted archive: daily Tue, 2026-09-08 02:00:00 +0200 [99a5671a...] (1/1)"} Saving the local cache at the end of :ref:`borg_create`:: diff --git a/docs/usage.rst b/docs/usage.rst index 02a74f95e2..7a3c887060 100644 --- a/docs/usage.rst +++ b/docs/usage.rst @@ -35,6 +35,7 @@ Usage .. toctree:: usage/general + usage/cockpit usage/repo-create usage/repo-space diff --git a/docs/usage/cockpit.rst b/docs/usage/cockpit.rst new file mode 100644 index 0000000000..b3cfd83904 --- /dev/null +++ b/docs/usage/cockpit.rst @@ -0,0 +1,105 @@ +.. highlight:: none +.. _cockpit: + +Cockpit +------- + +The cockpit is a full-screen terminal user interface showing what a borg command does +while it runs: its progress, its statistics, the file list and the log messages, all +updated live. To use it, put ``--cockpit`` in front of the command:: + + $ borg --cockpit -r /path/to/repo create --list my-files ~/Documents + $ borg --cockpit -r /path/to/repo extract --list my-files + $ borg --cockpit -r /path/to/repo check --repair + +The cockpit needs the ``textual`` package: ``pip install borgbackup[cockpit]`` installs +it, the binary releases include it (see :ref:`installation`). It needs a terminal of at +least 80x24 characters, a taller terminal gives the log more room. It does not start if +stdin, stdout or stderr is not a terminal (e.g. when run by cron or with redirected +output): it is an interactive display and stays on the screen until you quit it. + +How it works +~~~~~~~~~~~~ + +The cockpit runs the borg command as a subprocess with ``--log-json`` and ``--progress`` +added, and builds its display from the JSON output borg produces for frontends, see +:ref:`json_output`. Apart from that, the command runs exactly like it does without +``--cockpit``, with the options you gave it. + +.. note:: + + ``--progress`` makes ``extract`` and ``export-tar`` read the archive metadata once + more before they start, to determine the total amount of data for the progress bar, + so they start a bit later than usual, see :ref:`borg_extract`. + +The lower part of the screen is the log: borg's messages, warnings and errors, the file +list if you gave ``--list``, and everything else borg outputs. Control characters (a file +name can contain them, e.g. an ESC starting a terminal escape sequence) are shown as the +replacement character (U+FFFD) everywhere in the cockpit, so they can not affect the +terminal. The panel in the upper right depends on the command: + +``create``, ``import-tar``, ``recreate``, ``transfer`` + The statistics of the archive being created: the number of files, the original and + the deduplicated size, the counts of added, modified and unchanged files, the path + being processed and the throughput in files and bytes per second, with a history + graph. For ``create`` and ``import-tar``, the exact final statistics of the new + archive (what ``--stats`` prints) are shown in the panel and in the log when borg + has finished. + + These numbers are the statistics borg reports. They do not depend on ``--list`` and + ``--filter``, which only determine what the log shows. A ``-`` means that borg does + not report that number: ``transfer`` has no counts by status, and a ``--dry-run`` + only reports the number of files and the original size. + +``extract``, ``export-tar`` + A progress bar with the percentage and the estimated remaining time, the amount of + data extracted so far, the throughput and the counts of the ``--list`` lines. + +All other commands + The phases of the operation borg reports progress for, e.g. "Checking index" and + "Checking archives" for ``check``, each with a progress bar. For ``prune``, ``delete`` + and ``undelete`` with ``--list``, also the numbers of kept, pruned, deleted or undeleted + archives (marked as "dry-run" if nothing was changed). + +Every panel also shows the elapsed time, the number of warnings and errors and, when +borg has finished, its exit code. The cockpit stays on the screen until you press ``q``, +so you can have a look at the log and the numbers. It then exits with the exit code of +the borg command, see :ref:`return_codes`. + +Prompts and passphrases +~~~~~~~~~~~~~~~~~~~~~~~ + +When borg asks a yes/no question (e.g. ``check --repair`` asks whether you know what you +are doing), the cockpit shows a dialog: answer with the YES or NO button, or type another +answer into the input field. + +The cockpit can not enter a passphrase. Give it to borg via the environment, e.g. by +setting ``BORG_PASSPHRASE`` or ``BORG_PASSCOMMAND`` (see :ref:`env_vars`). Otherwise the +cockpit shows a hint that borg is waiting for a passphrase, and you have to quit and try +again. + +Commands the cockpit can not run +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + +The cockpit uses the terminal and borg's stdin is connected to the cockpit (that is how +the answers to prompts get to borg). Thus, the cockpit refuses to run: + +- commands reading from stdin: ``create`` with ``-`` as a path or with + ``--paths-from-stdin``, ``import-tar`` reading from ``-``, ``key import`` reading from + ``-`` or with ``--paper``, and ``serve``. +- commands writing their data to stdout: ``extract --stdout`` and ``export-tar`` writing + to ``-``. + +Keys +~~~~ + +``q`` (or Ctrl-C) + Quit. If borg is still running, quitting means terminating it, so the cockpit asks + for confirmation first: ``y`` terminates borg (SIGTERM), waits until it has exited and + quits; ``n``, Escape or Enter continue. When the cockpit gets a SIGTERM, SIGHUP or + SIGINT signal (e.g. because its terminal window gets closed), it terminates borg, + waits and exits without asking. + +``t`` + Toggle the universal translator: the labels are shown in Borg speak. Resistance is + futile. diff --git a/docs/usage_general.rst.inc b/docs/usage_general.rst.inc index 1b8d661e93..6e65e8c2f7 100644 --- a/docs/usage_general.rst.inc +++ b/docs/usage_general.rst.inc @@ -14,6 +14,8 @@ .. include:: usage/general/logging.rst.inc +.. _return_codes: + .. include:: usage/general/return-codes.rst.inc .. include:: usage/general/config.rst.inc diff --git a/src/borg/archive.py b/src/borg/archive.py index 541e69e2d2..123aa2f244 100644 --- a/src/borg/archive.py +++ b/src/borg/archive.py @@ -209,12 +209,11 @@ def show_progress(self, item=None, final=False, stream=None): stream = stream or sys.stderr self.last_progress = now if self.output_json: - if not final: - data = self.as_dict() - if item: - data |= text_to_json("path", item.path) - else: - data = {} + # the progress is rate limited, so the final object must have the final statistics: nothing + # else reports what was processed since the previous object (or all of a short operation). + data = self.as_dict() + if item and not final: + data |= text_to_json("path", item.path) data |= {"time": time.time(), "type": "archive_progress", "finished": final} msg = json.dumps(data) end = "\n" @@ -223,7 +222,7 @@ def show_progress(self, item=None, final=False, stream=None): if not final: # no width limit here, so always show the sizes precisely, see #3559. osize_fmt = format_file_size(self.osize, fine=True) - usize_fmt = format_file_size(self.usize, fine=True) + usize_fmt = format_file_size(self.usize or 0, fine=True) # None: unknown (dry-run) msg = f"{osize_fmt} O {usize_fmt} U {self.nfiles} N " msg += remove_surrogates(item.path) if item else "" else: @@ -236,7 +235,7 @@ def show_progress(self, item=None, final=False, stream=None): # if the terminal is clearly wider than the classic 80 columns, see #3559. fine = columns >= 110 osize_fmt = format_file_size(self.osize, fine=fine) - usize_fmt = format_file_size(self.usize, fine=fine) + usize_fmt = format_file_size(self.usize or 0, fine=fine) # None: unknown (dry-run) msg = f"{osize_fmt} O {usize_fmt} U {self.nfiles} N " path = remove_surrogates(item.path) if item else "" space = columns - swidth(msg) @@ -2122,7 +2121,8 @@ def process_hardlink(self, *, tarinfo, status, type): def process_file(self, *, tarinfo, status, type, tar): with self.create_helper(tarinfo, status, type) as (item, status): self.print_file_status(status, item.path) - status = None # we already printed the status + self.stats.files_stats[status] += 1 + status = None # we already printed and counted the status fd = tar.extractfile(tarinfo) self.digester.start() self.process_file_chunks( @@ -3001,6 +3001,7 @@ def __init__( dry_run=False, stats=False, progress=False, + log_json=False, file_status_printer=None, timestamp=None, ): @@ -3030,6 +3031,7 @@ def __init__( self.dry_run = dry_run self.stats = stats self.progress = progress + self.log_json = log_json # output the progress as archive_progress JSON objects self.print_file_status = file_status_printer or (lambda *args: None) def recreate(self, archive_info, target_name, delete_original, comment=None): @@ -3046,6 +3048,10 @@ def recreate(self, archive_info, target_name, delete_original, comment=None): def process_items(self, archive, target): matcher = self.matcher + if self.dry_run: + # the statistics of a dry-run are what would be in the new archive. what would be new to the + # repository (the deduplicated size) is unknown, see Statistics.as_dict(). + target.stats.usize = None for item in archive.iter_items(): if not matcher.match(item.path): @@ -3053,6 +3059,11 @@ def process_items(self, archive, target): continue if self.dry_run: self.print_file_status("+", item.path) # included + if "chunks" in item: + target.stats.nfiles += 1 + target.stats.osize += item.get_size() + if self.progress: + target.stats.show_progress(item=item) else: self.process_item(archive, target, item) if self.progress: @@ -3060,6 +3071,7 @@ def process_items(self, archive, target): def process_item(self, archive, target, item): status = file_status(item.mode) + target.stats.files_stats[status] += 1 if "chunks" in item: self.print_file_status(status, item.path) status = None @@ -3174,6 +3186,7 @@ def create_target_archive(self, name, chunker_params=None): name, create=True, progress=self.progress, + log_json=self.log_json, chunker_params=chunker_params or self.chunker_params, cache=self.cache, ) diff --git a/src/borg/archiver/__init__.py b/src/borg/archiver/__init__.py index caa320611a..c5de3a1cd9 100644 --- a/src/borg/archiver/__init__.py +++ b/src/borg/archiver/__init__.py @@ -38,6 +38,7 @@ from ..helpers import add_warning, BorgWarning, BackupWarning from ..helpers import format_file_size from ..helpers import remove_surrogates, text_to_json + from ..helpers import bin_to_hex, OutputTimestamp, BorgJsonEncoder from ..helpers import DatetimeWrapper, replace_placeholders from ..helpers.argparsing import flatten_namespace, ArgumentTypeError, ArgumentParser, SUPPRESS from ..helpers import is_slow_msgpack, is_supported_msgpack, sysinfo @@ -140,6 +141,9 @@ def __init__(self, lock_wait=None, prog=None): self.lock_wait = lock_wait self.prog = prog self.start_backup = None + # for print_file_status(): the commands with a file listing set these from their options. + self.output_list = False + self.output_filter = None def print_warning(self, msg, *args, **kw): warning_code = kw.get("wc", EXIT_WARNING) # note: wc=None can be used to not influence exit code @@ -171,6 +175,28 @@ def print_file_status(self, status, path): else: logging.getLogger("borg.output.list").info("%1s %s", status, remove_surrogates(path)) + def print_archive_status(self, status, archive_info, message, data=None, dry_run=False): + """ + List an archive a command processed, like print_file_status() lists the items of a file listing. + + With --log-json, an archive_status JSON object is printed: name, id and time of the archive, the + (e.g. "kept", "pruned", "deleted"), the (the text line) and the keys of . + tells that the status is what would be done: nothing was changed. + Without it, the text line goes to the "borg.output.list" logger. The callers check the --list options. + """ + if self.log_json: + json_data = { + "name": archive_info.name, + "archive": archive_info.name, + "id": bin_to_hex(archive_info.id), + "time": OutputTimestamp(archive_info.ts), + } + json_data |= data or {} + json_data |= {"status": status, "dry_run": dry_run, "type": "archive_status", "message": message} + print(json.dumps(json_data, cls=BorgJsonEncoder), file=sys.stderr) + else: + logging.getLogger("borg.output.list").info(message) + def preprocess_args(self, args): deprecations = [ # ('--old', '--new' or None, 'Warning: "--old" has been deprecated. Use "--new" instead.'), @@ -281,7 +307,12 @@ def build_parser(self): parser.add_argument( "-V", "--version", action="version", version="%(prog)s " + __version__, help="show version number and exit" ) - parser.add_argument("--cockpit", dest="cockpit", action="store_true", help="Start the Borg TUI") + parser.add_argument( + "--cockpit", + dest="cockpit", + action="store_true", + help="run the command in the cockpit TUI, a full-screen progress display", + ) parser.common_options.add_common_group(parser, provide_defaults=True) common_parser = ArgumentParser(prog=self.prog) @@ -647,6 +678,12 @@ def main(): # pragma: no cover if args.cockpit: # Cockpit TUI operation + from ..cockpit.runner import unsupported_reason # does not need textual + + reason = unsupported_reason(args) + if reason is not None: + print(f"borg --cockpit: {reason}", file=sys.stderr) + sys.exit(CommandError.exit_mcode if modern_ec else EXIT_ERROR) try: from ..cockpit.app import BorgCockpitApp except ImportError as err: @@ -655,10 +692,13 @@ def main(): # pragma: no cover print("Please install them using: pip install 'borgbackup[cockpit]'", file=sys.stderr) sys.exit(EXIT_ERROR) - app = BorgCockpitApp() - app.borg_args = [arg for arg in sys.argv[1:] if arg != "--cockpit"] + app = BorgCockpitApp( + borg_args=[arg for arg in sys.argv[1:] if arg != "--cockpit"], command=getattr(args, "subcommand", None) + ) app.run() - sys.exit(EXIT_SUCCESS) # borg subprocess RC was already shown on the TUI + # exit with the exit code of the borg subprocess (it was shown on the TUI); rc < 0: borg could not be run. + rc = app.session.rc + sys.exit(rc if rc is not None and rc >= 0 else EXIT_ERROR) # normal borg CLI operation try: diff --git a/src/borg/archiver/create_cmd.py b/src/borg/archiver/create_cmd.py index 472d373ef7..52530d7f25 100644 --- a/src/borg/archiver/create_cmd.py +++ b/src/borg/archiver/create_cmd.py @@ -12,6 +12,7 @@ from .. import helpers from ..archive import Archive, Statistics, is_special, SF_DATALESS from ..archive import BackupError, BackupOSError, BackupItemExcluded, backup_io, OsOpen, stat_update_check +from ..item import Item from ..archive import FilesystemObjectProcessors, MetadataCollector, ChunksProcessor from ..cache import Cache from ..constants import * # NOQA @@ -23,7 +24,7 @@ from ..helpers import read_input_map from ..helpers import eval_escapes from ..helpers import timestamp, archive_ts_now -from ..helpers import get_cache_dir, os_stat, get_strip_prefix, slashify +from ..helpers import get_cache_dir, os_stat, get_strip_prefix, slashify, make_path_safe from ..helpers import BackupBrokenSymlinkError from ..helpers import dir_is_tagged from ..helpers import log_multi @@ -176,6 +177,7 @@ def create_inner(archive, cache, fso): else: status = "+" # included self.dry_run_stats.nfiles += 1 # size unknown without running the command + self._dry_run_progress(path) self.print_file_status(status, path) elif args.paths_from_command or args.paths_from_shell_command or args.paths_from_stdin: paths_sep = eval_escapes(args.paths_delimiter) if args.paths_delimiter is not None else "\n" @@ -255,6 +257,7 @@ def create_inner(archive, cache, fso): else: status = "+" # included self.dry_run_stats.nfiles += 1 # size unknown without reading stdin + self._dry_run_progress(path) self.print_file_status(status, path) if not dry_run and status is not None: fso.stats.files_stats[status] += 1 @@ -291,9 +294,9 @@ def create_inner(archive, cache, fso): self.print_warning_instance(BackupWarning(path, e)) continue if not dry_run: + archive.stats += fso.stats # before the final progress, it reports the final statistics if args.progress: archive.stats.show_progress(final=True) - archive.stats += fso.stats if sig_int: # do not save the archive if the user ctrl-c-ed. raise Error("Got Ctrl-C / SIGINT.") @@ -308,7 +311,12 @@ def create_inner(archive, cache, fso): self.noxattrs = args.noxattrs self.exclude_dataless = args.exclude_dataless dry_run = args.dry_run - self.dry_run_stats = Statistics() if dry_run else None + # A dry-run has no archive: its statistics are what would be backed up. The deduplicated size is + # unknown then (None), see Statistics.as_dict(). + self.dry_run_stats = Statistics(output_json=args.log_json) if dry_run else None + if dry_run: + self.dry_run_stats.usize = None + self.dry_run_show_progress = dry_run and args.progress self.start_backup = time.time_ns() t0 = archive_ts_now() logger.info('Creating archive "%s" in repository %s' % (args.name, args.location.processed)) @@ -379,6 +387,8 @@ def create_inner(archive, cache, fso): log_multi(str(archive), str(archive.stats), logger=logging.getLogger("borg.output.stats")) else: create_inner(None, None, None) + if args.progress: + self.dry_run_stats.show_progress(final=True) args.stats |= args.json if args.stats: stats = self.dry_run_stats @@ -398,6 +408,11 @@ def create_inner(archive, cache, fso): logger=logging.getLogger("borg.output.stats"), ) + def _dry_run_progress(self, path): + """Report the progress of a dry-run (rate limited), like Archive.add_item() does it for a real run.""" + if self.dry_run_show_progress: + self.dry_run_stats.show_progress(item=Item(path=make_path_safe(path))) + def _process_any( self, *, path, parent_fd, name, st, fso, cache, read_special, dry_run, strip_prefix, followed_symlink=False ): @@ -425,6 +440,7 @@ def _process_any( special = is_special(st.st_mode) if special: stats.nfiles += 1 # size unknown without reading the special file + self._dry_run_progress(path) return "+" # included MAX_RETRIES = 10 # count includes the initial try (initial try == "retry 0") # if we followed a symlink, we must not refuse to open its target via the symlink: diff --git a/src/borg/archiver/delete_cmd.py b/src/borg/archiver/delete_cmd.py index f524ee5fad..376a41ed6b 100644 --- a/src/borg/archiver/delete_cmd.py +++ b/src/borg/archiver/delete_cmd.py @@ -1,5 +1,3 @@ -import logging - from ._common import with_repository, archive_match_patterns from ..constants import * # NOQA from ..helpers import format_archive, CommandError, bin_to_hex, archivename_validator @@ -38,7 +36,6 @@ def do_delete(self, args, repository): ) deleted = False - logger_list = logging.getLogger("borg.output.list") for i, archive_info in enumerate(archive_infos, 1): name, id, hex_id = archive_info.name, archive_info.id, bin_to_hex(archive_info.id) # format early before deletion of the archive @@ -54,7 +51,8 @@ def do_delete(self, args, repository): deleted = True if self.output_list: msg = "Would delete: {} ({}/{})" if dry_run else "Deleted archive: {} ({}/{})" - logger_list.info(msg.format(archive_formatted, i, count)) + message = msg.format(archive_formatted, i, count) + self.print_archive_status("deleted", archive_info, message, dry_run=dry_run) if dry_run: logger.info("Finished dry-run.") elif deleted: diff --git a/src/borg/archiver/extract_cmd.py b/src/borg/archiver/extract_cmd.py index 19b0e51f05..af1bee57cc 100644 --- a/src/borg/archiver/extract_cmd.py +++ b/src/borg/archiver/extract_cmd.py @@ -40,6 +40,7 @@ def do_extract(self, args, repository, manifest, archive): progress = args.progress output_list = args.output_list + self.output_list = output_list # for print_file_status() dry_run = args.dry_run stdout = args.stdout sparse = args.sparse @@ -80,8 +81,7 @@ def do_extract(self, args, repository, manifest, archive): is_matched = matcher.match(orig_path) if output_list: - log_prefix = "+" if is_matched else "-" - logging.getLogger("borg.output.list").info(f"{log_prefix} {remove_surrogates(item.path)}") + self.print_file_status("+" if is_matched else "-", item.path) if is_matched: if not dry_run: diff --git a/src/borg/archiver/prune_cmd.py b/src/borg/archiver/prune_cmd.py index 0e5efcfe93..4787416fb9 100644 --- a/src/borg/archiver/prune_cmd.py +++ b/src/borg/archiver/prune_cmd.py @@ -1,6 +1,5 @@ from typing import Callable, NamedTuple from datetime import datetime, timedelta -import logging import math from functools import partial, wraps import os @@ -251,7 +250,6 @@ def do_prune(self, args, repository, manifest): ) logger.info("Keeping %d archives, pruning %d archives.", len(keep), len(archives_to_prune)) - list_logger = logging.getLogger("borg.output.list") # set up counters for the progress display num_archives_deleted = 0 pi = ProgressIndicatorPercent(total=len(archives_to_prune), msg="Pruning archives %3.0f%%", msgid="prune") @@ -260,28 +258,30 @@ def do_prune(self, args, repository, manifest): break # get_item_data/format_item may internally load the archive from the repository, # so we must call it before deleting the archive. - if args.json: + if args.json or self.log_json: archive_data = formatter.get_item_data(archive_info, jsonline=True) archive_data["group"] = dict(zip(group_by, group_of[archive_info])) - else: + if not args.json: archive_formatted = formatter.format_item(archive_info, jsonline=False) if archive_info in archives_to_prune: if not args.json: pi.show() num_archives_deleted += 1 + status = "pruned" if args.dry_run: log_message = "Would prune:" else: log_message = f"Pruning archive ({num_archives_deleted}/{len(archives_to_prune)}):" manifest.archives.delete_by_id(archive_info.id) - if args.json: + if args.json or self.log_json: archive_data["kept"] = False archive_data["deleted_archive_number"] = num_archives_deleted else: result = keep[archive_info] result_message = f"{result.rule.key}{'[oldest]' if result.oldest else ''} #{result.idx + 1}" log_message = f"Keeping archive (rule: {result_message}):" - if args.json: + status = "kept" + if args.json or self.log_json: archive_data["kept"] = True archive_data["keep_rule"] = result.rule.key archive_data["kept_oldest"] = result.oldest @@ -299,7 +299,9 @@ def do_prune(self, args, repository, manifest): or (args.list_pruned and archive_info in archives_to_prune) or (args.list_kept and archive_info not in archives_to_prune) ): - list_logger.info(f"{log_message:<44} {archive_formatted}") + message = f"{log_message:<44} {archive_formatted}" + data = archive_data if self.log_json else None + self.print_archive_status(status, archive_info, message, data, dry_run=args.dry_run) if not args.json: pi.finish() if args.json: diff --git a/src/borg/archiver/recreate_cmd.py b/src/borg/archiver/recreate_cmd.py index 7d67131282..c654325b09 100644 --- a/src/borg/archiver/recreate_cmd.py +++ b/src/borg/archiver/recreate_cmd.py @@ -31,6 +31,7 @@ def do_recreate(self, args, repository, manifest, cache): # args.compression is not passed here: the with_repository decorator has already # set repo_objs.compressor from it, which compresses everything newly written. progress=args.progress, + log_json=args.log_json, stats=args.stats, file_status_printer=self.print_file_status, dry_run=args.dry_run, diff --git a/src/borg/archiver/tar_cmds.py b/src/borg/archiver/tar_cmds.py index daf73e86ab..630974a92f 100644 --- a/src/borg/archiver/tar_cmds.py +++ b/src/borg/archiver/tar_cmds.py @@ -397,6 +397,7 @@ def _export_tar(self, args, archive, tarstream): progress = args.progress output_list = args.output_list + self.output_list = output_list # for print_file_status() strip_components = args.strip_components hlm = HardLinkManager(id_type=bytes, info_type=str) # hlid -> path @@ -501,7 +502,7 @@ def sparsify_tarinfo(item, tarinfo): if args.tar_format in ("BORG", "PAX"): tarinfo.pax_headers = item_to_paxheaders(args.tar_format, item) if output_list: - logging.getLogger("borg.output.list").info(remove_surrogates(orig_path)) + self.print_file_status("+", orig_path) sparse_content = sparsify_tarinfo(item, tarinfo) if args.sparse and needs_content else None if sparse_content is not None: stream_plan, map_bytes = sparse_content @@ -607,13 +608,15 @@ def path_components(name): status = "E" self.print_warning("%s: Unsupported tarinfo type %s", tarinfo.name, tarinfo.type) self.print_file_status(status, name) + if status is not None: # None: process_file already printed and counted the status + tfo.stats.files_stats[status] += 1 # This does not close the fileobj (tarstream) we passed to it -- a side effect of the | mode. tar.close() + archive.stats += tfo.stats # before the final progress, it reports the final statistics if args.progress: archive.stats.show_progress(final=True) - archive.stats += tfo.stats archive.save(comment=args.comment, timestamp=args.timestamp) args.stats |= args.json if args.stats: diff --git a/src/borg/archiver/transfer_cmd.py b/src/borg/archiver/transfer_cmd.py index 56750aab61..5dc49e096e 100644 --- a/src/borg/archiver/transfer_cmd.py +++ b/src/borg/archiver/transfer_cmd.py @@ -219,7 +219,9 @@ def do_transfer(self, args, *, repository, manifest, cache, other_repository=Non print(f"{name} {ts_str} {id_hex}: copying archive to destination repo...") other_archive = Archive(other_manifest, archive_info) archive = ( - Archive(manifest, name, cache=cache, create=True, progress=args.progress) if not dry_run else None + Archive(manifest, name, cache=cache, create=True, progress=args.progress, log_json=args.log_json) + if not dry_run + else None ) upgrader.new_archive(archive=archive) for item in other_archive.iter_items(): diff --git a/src/borg/archiver/undelete_cmd.py b/src/borg/archiver/undelete_cmd.py index b7d1bd4ac5..b6a4b07034 100644 --- a/src/borg/archiver/undelete_cmd.py +++ b/src/borg/archiver/undelete_cmd.py @@ -1,5 +1,3 @@ -import logging - from ._common import with_repository, archive_match_patterns from ..constants import * # NOQA from ..helpers import format_archive, CommandError, bin_to_hex, archivename_validator @@ -35,7 +33,6 @@ def do_undelete(self, args, repository): raise CommandError("Aborting: if you really want to undelete all archives, please use -a 'sh:*'.") undeleted = False - logger_list = logging.getLogger("borg.output.list") for i, archive_info in enumerate(archive_infos, 1): name, id, hex_id = archive_info.name, archive_info.id, bin_to_hex(archive_info.id) try: @@ -47,7 +44,8 @@ def do_undelete(self, args, repository): undeleted = True if self.output_list: msg = "Would undelete: {} ({}/{})" if dry_run else "Undeleted archive: {} ({}/{})" - logger_list.info(msg.format(format_archive(archive_info), i, count)) + message = msg.format(format_archive(archive_info), i, count) + self.print_archive_status("undeleted", archive_info, message, dry_run=dry_run) if dry_run: logger.info("Finished dry-run.") elif undeleted: diff --git a/src/borg/cockpit/app.py b/src/borg/cockpit/app.py index e1ed1419ed..387007daeb 100644 --- a/src/borg/cockpit/app.py +++ b/src/borg/cockpit/app.py @@ -3,12 +3,13 @@ """ import asyncio -import time +import signal -from textual.app import App, ComposeResult -from textual.widgets import Header, Footer -from textual.containers import Horizontal, Container +from textual.app import App +from textual.css.query import NoMatches +from .events import Question +from .session import Session from .theme import theme @@ -21,20 +22,39 @@ class BorgCockpitApp(App): CSS_PATH = "cockpit.tcss" BINDINGS = [("q", "quit", "Quit"), ("ctrl+c", "quit", "Quit"), ("t", "toggle_translator", "Toggle Translator")] - def compose(self) -> ComposeResult: - """Create child widgets for the app.""" - from .widgets import LogoPanel, StatusPanel, StandardLog - - yield Header(show_clock=True) - - with Container(id="main-grid"): - with Horizontal(id="top-row"): - yield LogoPanel(id="logopanel") - yield StatusPanel(id="status") - - yield StandardLog(id="standard-log") - - yield Footer() + SPEED_INTERVAL = 1.0 # seconds between two speed samples (one sparkline column each) + REFRESH_INTERVAL = 0.2 # seconds between two refreshes of the widgets from the session + # These commands output the statistics of the new archive as JSON on stdout when given --json. + FINAL_STATS_COMMANDS = ("create", "import-tar") + QUIT_DELAY = 2.0 # seconds the final state stays on the screen (the logo fades out) before the cockpit exits + # The signals asking the cockpit to end, see handle_signals(). + SIGNALS = ("SIGTERM", "SIGHUP", "SIGINT") + + def __init__(self, borg_args=None, command=None, runner_factory=None, **kwargs): + """ + :param borg_args: the borg command line to run, without --cockpit [borg --version]. + :param command: the borg subcommand in borg_args, e.g. "create"; it selects the screen [None: generic]. + :param runner_factory: callable(args, callback, json_stdout=...) giving a BorgRunner-like object, for tests. + """ + super().__init__(**kwargs) + self.borg_args = ["--version"] if borg_args is None else list(borg_args) + self.command = command + self.json_stdout = command in self.FINAL_STATS_COMMANDS + self.runner_factory = runner_factory + self.session = Session(command=command, capture_stdout=self.json_stdout) + self.main_screen = None + self.runner = None + self.runner_task = None + self.quitting = False # the user quits: quit_app() runs + self.handled_signals = [] # the names of the signals handled by on_signal() + self.terminate_task = None + + def get_default_screen(self): + """The screen for the command that runs (Textual calls this when the app starts).""" + from .screens import screen_for_command + + self.main_screen = screen_for_command(self.command)() + return self.main_screen def get_theme_variable_defaults(self): # make these variables available to ALL themes @@ -53,9 +73,6 @@ def on_load(self) -> None: def on_mount(self) -> None: """Initialize components.""" - self.query_one("#logo").styles.animate("opacity", 1, duration=1) - self.query_one("#slogan").styles.animate("opacity", 1, duration=1) - # Delay runner start until after widgets are fully mounted self.call_after_refresh(self.start_runner) @@ -63,44 +80,110 @@ def start_runner(self) -> None: """Start the Borg runner after all widgets are mounted.""" from .runner import BorgRunner - # Speed tracking - self.total_lines_processed = 0 - self.last_lines_processed = 0 - self.speed_timer = self.set_interval(1.0, self.compute_speed) - - self.start_time = time.monotonic() - self.process_running = True - args = getattr(self, "borg_args", ["--version"]) # Default to safe command if none passed - self.runner = BorgRunner(args, self.handle_log_event) + factory = self.runner_factory or BorgRunner + self.runner = factory(self.borg_args, self.handle_event, json_stdout=self.json_stdout) self.runner_task = asyncio.create_task(self.runner.start()) + self.speed_timer = self.set_interval(self.SPEED_INTERVAL, self.sample_speed) + self.refresh_timer = self.set_interval(self.REFRESH_INTERVAL, self.refresh_from_session) + self.handle_signals() + + def handle_signals(self) -> None: + """ + End in an orderly way when a signal asks the cockpit to end (e.g. the terminal window gets closed). + + borg's main() has installed handlers raising an exception for these signals. Raised at some random + place inside the event loop, it would end the app with a traceback, without waiting for borg. + The event loop's signal handlers replace them while the app runs. + """ + loop = asyncio.get_running_loop() + for name in self.SIGNALS: + signum = getattr(signal, name, None) + if signum is None: + continue # no such signal on this platform + try: + loop.add_signal_handler(signum, self.on_signal, name) + except (NotImplementedError, ValueError, RuntimeError): + continue # not supported by this event loop (Windows) or not running in the main thread + self.handled_signals.append(name) + + def on_signal(self, name) -> None: + """Got a signal: terminate borg, wait for it and exit; main() then exits with borg's exit code.""" + if self.terminate_task is None: + self.terminate_task = asyncio.create_task(self.terminate()) + + async def terminate(self) -> None: + await self.stop_borg() + self.exit() - def compute_speed(self) -> None: - """Calculate and update speed (lines per second).""" - current_lines = self.total_lines_processed - lines_per_second = float(current_lines - self.last_lines_processed) - self.last_lines_processed = current_lines - - status_panel = self.query_one("#status") - status_panel.update_speed(lines_per_second / 1000) - if self.process_running: - status_panel.elapsed_time = time.monotonic() - self.start_time + @property + def process_running(self): + return self.session.running + + def handle_event(self, event) -> None: + """Process an event from the runner: the session does the bookkeeping, a prompt needs a dialog.""" + self.session.feed(event) + if isinstance(event, Question) and event.needs_answer: + from .prompt import PromptModal + + self.push_screen(PromptModal(event.message), callback=self.send_answer) + + def send_answer(self, answer) -> None: + """Send the answer given in the prompt dialog to borg.""" + if answer is not None and self.runner is not None: + self.run_worker(self.runner.answer(answer)) + + def sample_speed(self) -> None: + """Compute the current rates and show them.""" + self.session.sample() + try: + self.main_screen.sample_speed(self.session) + except NoMatches: + pass # the widgets are being torn down (the app exits), the timer still fires + + def refresh_from_session(self) -> None: + """Show the current state of the session in the widgets.""" + try: + self.main_screen.refresh_from_session(self.session) + except NoMatches: + pass # see sample_speed() async def on_unmount(self) -> None: """Cleanup resources on app shutdown.""" - if hasattr(self, "runner"): + if self.runner is not None: + await self.runner.stop() + + async def stop_borg(self) -> None: + """Terminate borg if it still runs, and wait until it has exited.""" + if self.runner is not None: await self.runner.stop() + if self.runner_task is not None: + await self.runner_task async def action_quit(self) -> None: - """Handle quit action.""" + """Quit. Quitting terminates borg, so if borg still runs, ask for confirmation first.""" + from .prompt import ConfirmQuitModal + + if self.quitting: + return + if self.session.running and self.runner is not None: + if not isinstance(self.screen, ConfirmQuitModal): + self.push_screen(ConfirmQuitModal(), callback=self.quit_confirmed) + return + await self.quit_app() + + def quit_confirmed(self, confirmed) -> None: + """The answer given in the quit confirmation dialog.""" + if confirmed: + self.run_worker(self.quit_app()) + + async def quit_app(self) -> None: + """Terminate borg if it still runs, keep the final state on the screen for a moment, then exit.""" + self.quitting = True if hasattr(self, "speed_timer"): self.speed_timer.stop() - if hasattr(self, "runner"): - await self.runner.stop() - if hasattr(self, "runner_task"): - await self.runner_task - self.query_one("#logo").styles.animate("opacity", 0, duration=2) - self.query_one("#slogan").styles.animate("opacity", 0, duration=2) - await asyncio.sleep(2) # give the user a chance the see the borg RC + await self.stop_borg() + self.main_screen.fade_out() + await asyncio.sleep(self.QUIT_DELAY) # give the user a chance the see the borg RC self.exit() def action_toggle_translator(self) -> None: @@ -108,22 +191,4 @@ def action_toggle_translator(self) -> None: from .translator import TRANSLATOR TRANSLATOR.toggle() - # Refresh dynamic UI elements - self.query_one("#status").refresh_ui_labels() - self.query_one("#standard-log").update_title() - self.query_one("#slogan").update_slogan() - - def handle_log_event(self, data: dict): - """Process a event from BorgRunner.""" - msg_type = data.get("type", "log") - - if msg_type == "stream_line": - self.total_lines_processed += 1 - line = data.get("line", "") - widget = self.query_one("#standard-log") - widget.add_line(line) - - elif msg_type == "process_finished": - self.process_running = False - rc = data.get("rc", 0) - self.query_one("#status").rc = rc + self.main_screen.refresh_ui_labels() diff --git a/src/borg/cockpit/cockpit.tcss b/src/borg/cockpit/cockpit.tcss index 8b8f401649..863e644552 100644 --- a/src/borg/cockpit/cockpit.tcss +++ b/src/borg/cockpit/cockpit.tcss @@ -76,8 +76,8 @@ Footer { border: double $primary; /* If content grows too large, scroll rather than pushing the log off-screen */ overflow-y: auto; - /* Adjust this if status or logo panel shall get more/less height. */ - height: 16; + /* The screens set the height to what their status panel needs (see CockpitScreen). */ + height: 19; } #logopanel { @@ -173,7 +173,6 @@ Pulsar.dim { #speed-sparkline { width: 100%; height: 4; - margin-bottom: 1; } .status { @@ -199,3 +198,68 @@ Pulsar.dim { .rc-error { color: $error; } + +/* The dialog for borg's yes/no prompts */ +/* The dialogs. Their background is translucent (unlike the one of the other screens, see Screen above), + so the cockpit stays visible behind them. */ +PromptModal, ConfirmQuitModal { + align: center middle; + background: $background 60%; +} + +#prompt-dialog { + width: 80%; + max-width: 100; + height: auto; + border: double $primary; + background: $surface; + padding: 1 2; +} + +#prompt-message { + height: auto; + margin-bottom: 1; +} + +#prompt-buttons { + height: auto; + align-horizontal: center; +} + +#prompt-buttons Button { + margin: 0 2; +} + +/* The progress bar of the extract screen: bar, percentage and ETA over the full panel width */ +#extract-bar { + width: 100%; +} + +#extract-bar Bar { + width: 1fr; +} + +#extract-bar Bar > .bar--bar { + color: $primary; + background: $panel; +} + +#extract-bar Bar > .bar--indeterminate { + color: $primary; + background: $panel; +} + +#extract-bar Bar > .bar--complete { + color: $success; + background: $panel; +} + +/* The lines of the status panels take only the height they need, what follows them comes right after. */ +#statuses { + height: auto; +} + +/* The phase list of the generic screen */ +#phases { + height: auto; +} diff --git a/src/borg/cockpit/events.py b/src/borg/cockpit/events.py new file mode 100644 index 0000000000..d575b95b15 --- /dev/null +++ b/src/borg/cockpit/events.py @@ -0,0 +1,219 @@ +""" +Borg Cockpit - typed events. + +The runner turns the JSON lines borg writes to stderr with --log-json into the event objects defined +here (see docs/internals/frontends.rst for the JSON API), so that the rest of the cockpit never deals +with raw dicts. Everything else the runner observes (stdout lines, non-JSON stderr lines, the process +exit) is an event as well. +""" + +import json +from dataclasses import dataclass, field + + +@dataclass(frozen=True) +class Event: + """Base class of everything the runner hands to the application.""" + + +@dataclass(frozen=True) +class LogMessage(Event): + """log_message: regular log output (--info, --debug, warnings, errors).""" + + message: str + levelname: str = "INFO" + name: str = "" + msgid: str | None = None + time: float = 0.0 + + +@dataclass(frozen=True) +class ProgressMessage(Event): + """progress_message: what borg is working on, without a quantitative progress.""" + + operation: int + message: str + msgid: str | None = None + finished: bool = False + time: float = 0.0 + + +@dataclass(frozen=True) +class ProgressPercent(Event): + """progress_percent: progress with a current and a total value.""" + + operation: int + message: str + current: int | None = None + total: int | None = None + info: list | None = None + msgid: str | None = None + finished: bool = False + time: float = 0.0 + + +@dataclass(frozen=True) +class ArchiveProgress(Event): + """archive_progress: statistics while an archive is being created (create, import-tar, recreate, transfer).""" + + original_size: int = 0 + deduplicated_size: int = 0 + nfiles: int = 0 + hashing_time: float = 0.0 + chunking_time: float = 0.0 + files_stats: dict = field(default_factory=dict) + path: str | None = None + finished: bool = False + time: float = 0.0 + + +@dataclass(frozen=True) +class FileStatus(Event): + """file_status: one line of the --list output of create, import-tar and recreate.""" + + status: str + path: str + + +@dataclass(frozen=True) +class ArchiveStatus(Event): + """archive_status: one archive listed by prune, delete or undelete.""" + + name: str + status: str # kept, pruned, deleted, undeleted + message: str # the text line of the listing + dry_run: bool = False # the status is what would be done + data: dict = field(default_factory=dict) # the whole object, see the frontends docs for its keys + + +@dataclass(frozen=True) +class Question(Event): + """question_*: a yes/no prompt (kind "prompt" / "prompt_retry") or a message about how a prompt was answered.""" + + kind: str + message: str + msgid: str | None = None + env_var: str | None = None + + @property + def needs_answer(self): + """Is borg waiting for an answer on stdin?""" + return self.kind in ("prompt", "prompt_retry") + + +@dataclass(frozen=True) +class UnknownJson(Event): + """A JSON object with a type the cockpit does not know.""" + + data: dict + + +@dataclass(frozen=True) +class RawLine(Event): + """A line that is not a JSON object: stdout output, or stderr output written outside of --log-json.""" + + stream: str # "stdout" or "stderr" + line: str + partial: bool = False # True: not terminated by a newline (yet), e.g. a prompt waiting for input + + +@dataclass(frozen=True) +class ProcessFinished(Event): + """The borg process has exited (or could not be started: rc -1 and an error message).""" + + rc: int + error: str | None = None + + +def _opt_int(value): + """An int for JSON numbers, None for anything else (missing, null, ...).""" + if isinstance(value, bool) or not isinstance(value, (int, float)): + return None + return int(value) + + +def _float(value): + return float(value) if isinstance(value, (int, float)) and not isinstance(value, bool) else 0.0 + + +def _opt_str(value): + return value if isinstance(value, str) else None + + +def parse_json_line(line): + """ + Parse one line of borg's --log-json output into an Event. + + Returns None if the line is not a JSON object with a "type" key, so that the caller can pass it + on as a RawLine. Unknown types give an UnknownJson event, missing keys get defaults: the cockpit + must keep working with older and newer borg versions. + """ + try: + data = json.loads(line) + except ValueError: + return None + if not isinstance(data, dict) or not isinstance(data.get("type"), str): + return None + msg_type = data["type"] + message = _opt_str(data.get("message")) or "" + msgid = _opt_str(data.get("msgid")) + timestamp = _float(data.get("time")) + finished = bool(data.get("finished", False)) + if msg_type == "log_message": + return LogMessage( + message=message, + levelname=_opt_str(data.get("levelname")) or "INFO", + name=_opt_str(data.get("name")) or "", + msgid=msgid, + time=timestamp, + ) + if msg_type == "progress_message": + return ProgressMessage( + operation=_opt_int(data.get("operation")) or 0, + message=message, + msgid=msgid, + finished=finished, + time=timestamp, + ) + if msg_type == "progress_percent": + info = data.get("info") + return ProgressPercent( + operation=_opt_int(data.get("operation")) or 0, + message=message, + current=_opt_int(data.get("current")), + total=_opt_int(data.get("total")), + info=list(info) if isinstance(info, list) else None, + msgid=msgid, + finished=finished, + time=timestamp, + ) + if msg_type == "archive_progress": + files_stats = data.get("files_stats") + if not isinstance(files_stats, dict): + files_stats = {} + return ArchiveProgress( + original_size=_opt_int(data.get("original_size")) or 0, + deduplicated_size=_opt_int(data.get("deduplicated_size")) or 0, + nfiles=_opt_int(data.get("nfiles")) or 0, + hashing_time=_float(data.get("hashing_time")), + chunking_time=_float(data.get("chunking_time")), + files_stats={status: count for status, count in files_stats.items() if isinstance(count, int)}, + path=_opt_str(data.get("path")), + finished=finished, + time=timestamp, + ) + if msg_type == "file_status": + return FileStatus(status=_opt_str(data.get("status")) or "?", path=_opt_str(data.get("path")) or "") + if msg_type == "archive_status": + return ArchiveStatus( + name=_opt_str(data.get("name")) or "", + status=_opt_str(data.get("status")) or "", + message=message, + dry_run=data.get("dry_run") is True, + data=data, + ) + if msg_type.startswith("question_"): + return Question( + kind=msg_type[len("question_") :], message=message, msgid=msgid, env_var=_opt_str(data.get("env_var")) + ) + return UnknownJson(data) diff --git a/src/borg/cockpit/prompt.py b/src/borg/cockpit/prompt.py new file mode 100644 index 0000000000..b4b2a640c7 --- /dev/null +++ b/src/borg/cockpit/prompt.py @@ -0,0 +1,67 @@ +""" +Borg Cockpit - modal dialogs: borg's yes/no prompts and the confirmation for quitting while borg runs. +""" + +from textual.app import ComposeResult +from textual.containers import Horizontal, Vertical +from textual.screen import ModalScreen +from textual.widgets import Button, Input, Static + +from .widgets import printable + + +class PromptModal(ModalScreen[str]): + """ + Shows the message of a question_prompt and returns the answer to send to borg's stdin. + + The buttons send YES / NO, which borg accepts for all its prompts, including the "Type 'YES'" ones. + The input field is for anything else, e.g. an empty answer to select the default. + """ + + def __init__(self, message): + super().__init__() + self.message = printable(message, multiline=True) # it can contain paths, archive names, ... + + def compose(self) -> ComposeResult: + with Vertical(id="prompt-dialog"): + yield Static(self.message, id="prompt-message", markup=False) + yield Input(placeholder="other answer, Enter sends it", id="prompt-input") + with Horizontal(id="prompt-buttons"): + yield Button("YES", id="prompt-yes", variant="success") + yield Button("NO", id="prompt-no", variant="error") + + def on_button_pressed(self, event: Button.Pressed) -> None: + self.dismiss("YES" if event.button.id == "prompt-yes" else "NO") + + def on_input_submitted(self, event: Input.Submitted) -> None: + self.dismiss(event.value) + + +class ConfirmQuitModal(ModalScreen[bool]): + """ + Asks whether to really quit while borg is still running, because quitting terminates borg. + + Returns True to terminate borg and quit. The harmless button comes first, so it has the focus + and Enter selects it; Escape means the same. + """ + + BINDINGS = [ + ("y", "answer(True)", "Terminate borg and quit"), + ("n", "answer(False)", "Continue"), + ("escape", "answer(False)", "Continue"), + ] + + def compose(self) -> ComposeResult: + with Vertical(id="prompt-dialog"): + yield Static( + "borg is still running. Quitting the cockpit terminates it.", id="prompt-message", markup=False + ) + with Horizontal(id="prompt-buttons"): + yield Button("Continue (n)", id="quit-no", variant="success") + yield Button("Terminate borg and quit (y)", id="quit-yes", variant="error") + + def on_button_pressed(self, event: Button.Pressed) -> None: + self.dismiss(event.button.id == "quit-yes") + + def action_answer(self, terminate: bool) -> None: + self.dismiss(terminate) diff --git a/src/borg/cockpit/runner.py b/src/borg/cockpit/runner.py index 010d39449a..015482a76c 100644 --- a/src/borg/cockpit/runner.py +++ b/src/borg/cockpit/runner.py @@ -1,74 +1,209 @@ """ -Borg Runner - Manages Borg subprocess execution and output parsing. +Borg Runner - runs borg as a subprocess and turns its output into events. """ import asyncio import logging import os import sys -from collections.abc import Callable + +from ..platformflags import is_win32 +from .events import ProcessFinished, RawLine, parse_json_line + +# The options the cockpit needs for machine-readable output. They are common options, so they are +# valid in front of the subcommand; borg merges them with the options the user gave at any level. +INJECTED_OPTIONS = ("--log-json", "--progress") + + +def borg_command(args, executable=None, json_stdout=False): + """ + Build the command line to run borg with the given args and the cockpit's options injected. + + :param args: the borg command line (without the borg executable and without --cockpit). + :param executable: the command prefix starting borg [the interpreter / pyinstaller binary running this code]. + :param json_stdout: also add --json, so the command outputs its final results as JSON on stdout. + """ + if executable is None: + if getattr(sys, "frozen", False): + executable = [sys.executable] # sys.executable is the pyinstaller-made binary + else: + executable = [sys.executable, "-m", "borg"] + args = list(args) + if json_stdout and "--json" not in args: + # --json is an option of the subcommand, so it must come after it: at the end of the command line, + # or before a "--" end-of-options marker (as used by e.g. --paths-from-command). + args.insert(args.index("--") if "--" in args else len(args), "--json") + injected = [option for option in INJECTED_OPTIONS if option not in args] + return list(executable) + injected + args + + +def unsupported_reason(args, streams=None): + """ + Why the cockpit can not run the borg command given by the parsed command line ; None if it can. + + borg's stdin is a pipe from the cockpit (for the answers to borg's prompts) that stays open as long + as borg runs, and the terminal is used by the TUI: a command waiting for data on stdin would wait forever. + + The TUI reads the keys from stdin and draws to stderr (on Windows: to stdout). Without a terminal, it + would write its escape sequences to wherever the output goes and wait forever for the key that quits it. + + :param streams: the stdin, stdout and stderr of the cockpit [sys.stdin, sys.stdout, sys.stderr], for tests. + """ + command = getattr(args, "subcommand", None) + reads_stdin = ( + ( + command == "create" + and ("-" in (getattr(args, "paths", None) or []) or getattr(args, "paths_from_stdin", False)) + ) + or (command == "import-tar" and getattr(args, "tarfile", None) == "-") + or (command == "key import" and (getattr(args, "path", None) == "-" or getattr(args, "paper", False))) + or command == "serve" + ) + if reads_stdin: + return "this command reads from stdin, that does not work in the cockpit." + # borg's stdout is a pipe to the cockpit, which expects text lines (or the --json output) there. + writes_data_to_stdout = (command == "extract" and getattr(args, "stdout", False)) or ( + command == "export-tar" and getattr(args, "tarfile", None) == "-" + ) + if writes_data_to_stdout: + return "this command writes its data to stdout, that does not work in the cockpit." + if streams is None: + streams = (sys.stdin, sys.stdout, sys.stderr) + if not all(stream is not None and stream.isatty() for stream in streams): + return "it needs a terminal: stdin, stdout and stderr must not be redirected." + return None class BorgRunner: """ - Manages the execution of the borg subprocess and parses its JSON output. + Runs borg as a subprocess, parses its output into events and hands them to a callback, one at a time. + + stderr carries the --log-json stream, one JSON object per line, see docs/internals/frontends.rst. + Everything else (stdout lines, stderr lines that are not JSON) is passed on as RawLine events. + stdin is a pipe, so that the application can answer borg's yes/no prompts via answer(). + + On POSIX, borg runs in a new session and thus has no controlling terminal: nothing it does can + mess with the terminal the TUI runs on. A passphrase prompt then falls back to stderr/stdin, where + the cockpit sees it (see Session), instead of being painted over the TUI. """ - def __init__(self, command: list[str], log_callback: Callable[[dict], None]): - self.command = command - self.log_callback = log_callback - self.process: asyncio.subprocess.Process | None = None - self.logger = logging.getLogger(__name__) + READ_SIZE = 64 * 1024 + # A line longer than this [bytes] is no line borg made for a frontend or a user, but bulk data: only + # its start is passed on, the rest is dropped. This bounds the memory needed for an unterminated line. + LINE_MAX = 1024 * 1024 + LINE_MAX_SHOWN = 200 # bytes passed on of a line longer than LINE_MAX + # An unterminated line (e.g. a prompt waiting for input) is passed on after this idle time [seconds]. + PARTIAL_LINE_TIMEOUT = 1.0 + # How long to wait for borg to finish after SIGTERM before killing it [seconds]. + TERMINATE_TIMEOUT = 10.0 - async def start(self): + def __init__(self, args, callback, *, executable=None, json_stdout=False): """ - Starts the Borg subprocess and processes its output. + :param args: the borg command line (without the borg executable and without --cockpit). + :param callback: called with each Event, the last one being ProcessFinished. + :param executable: see borg_command(), for tests. + :param json_stdout: see borg_command(). """ + self.args = list(args) + self.callback = callback + self.executable = executable + self.json_stdout = json_stdout + self.process = None + self.logger = logging.getLogger(__name__) + + async def start(self): + """Run borg to completion, handing all events to the callback.""" if self.process is not None: self.logger.warning("Borg process already running.") return - - if getattr(sys, "frozen", False): - cmd = [sys.executable] + self.command # executable == pyinstaller binary - else: - cmd = [sys.executable, "-m", "borg"] + self.command # executable == python interpreter - + cmd = borg_command(self.args, self.executable, self.json_stdout) self.logger.info(f"Starting Borg process: {cmd}") - env = os.environ.copy() env["PYTHONUNBUFFERED"] = "1" - + # --cockpit is removed from the command line, but the option can also be set by the environment + # or by borg's config file; the environment overrides the config file. Without this, the borg + # started here would start a cockpit again. + env["BORG_COCKPIT"] = "false" + kwargs = {} if is_win32 else {"start_new_session": True} try: self.process = await asyncio.create_subprocess_exec( - *cmd, stdout=asyncio.subprocess.PIPE, stderr=asyncio.subprocess.PIPE, env=env + *cmd, + stdin=asyncio.subprocess.PIPE, + stdout=asyncio.subprocess.PIPE, + stderr=asyncio.subprocess.PIPE, + env=env, + **kwargs, ) - - async def read_stream(stream, stream_name): - while line := await stream.readline(): - decoded_line = line.decode("utf-8", errors="replace").rstrip() - if decoded_line: - self.log_callback({"type": "stream_line", "stream": stream_name, "line": decoded_line}) - - # Read both streams concurrently - await asyncio.gather(read_stream(self.process.stdout, "stdout"), read_stream(self.process.stderr, "stderr")) - + await asyncio.gather(self._read(self.process.stdout, "stdout"), self._read(self.process.stderr, "stderr")) rc = await self.process.wait() - self.log_callback({"type": "process_finished", "rc": rc}) - + self.callback(ProcessFinished(rc=rc)) except Exception as e: self.logger.error(f"Failed to run Borg process: {e}") - self.log_callback({"type": "process_finished", "rc": -1, "error": str(e)}) + self.callback(ProcessFinished(rc=-1, error=str(e))) finally: self.process = None - async def stop(self): + async def _read(self, stream, name): """ - Stops the Borg subprocess if it is running. + Pass on the lines of ; an unterminated line is passed on as partial after some idle time. + + Of a line longer than LINE_MAX, only the start is passed on (as partial), the rest is dropped. """ - if self.process and self.process.returncode is None: + buffer = b"" + overlong = False # inside a line longer than LINE_MAX: its start was passed on, the rest gets dropped + while True: + try: + data = await asyncio.wait_for(stream.read(self.READ_SIZE), self.PARTIAL_LINE_TIMEOUT) + except TimeoutError: + if buffer: + self._line(name, buffer, partial=True) + buffer = b"" + continue + if not data: # EOF + if buffer: + self._line(name, buffer) + return + *lines, buffer = (buffer + data).split(b"\n") + for line in lines: + if overlong: + overlong = False # that was the end of the overlong line + else: + self._line(name, line) + if overlong: + buffer = b"" + elif len(buffer) > self.LINE_MAX: + self._line(name, buffer[: self.LINE_MAX_SHOWN] + b" [...]", partial=True) + overlong, buffer = True, b"" + + def _line(self, stream, raw, partial=False): + line = raw.decode("utf-8", errors="replace").rstrip("\r") + if not line.strip(): + return + event = parse_json_line(line) if stream == "stderr" and not partial else None + self.callback(event if event is not None else RawLine(stream=stream, line=line, partial=partial)) + + async def answer(self, text): + """Send the answer to a prompt to borg's stdin.""" + process = self.process + if process is None or process.stdin is None: + return + try: + process.stdin.write((text + "\n").encode("utf-8")) + await process.stdin.drain() + except (OSError, ValueError) as e: # borg is gone or its stdin is closed + self.logger.warning(f"Could not send the answer to borg: {e}") + + async def stop(self): + """Terminate borg if it is still running; borg handles SIGTERM by finishing in an orderly way.""" + process = self.process + if process is not None and process.returncode is None: self.logger.info("Terminating Borg process...") try: - self.process.terminate() - await self.process.wait() + process.terminate() + try: + await asyncio.wait_for(process.wait(), self.TERMINATE_TIMEOUT) + except TimeoutError: + process.kill() + await process.wait() except ProcessLookupError: - pass # Process already dead + pass # already dead diff --git a/src/borg/cockpit/screens.py b/src/borg/cockpit/screens.py new file mode 100644 index 0000000000..78c7eb7417 --- /dev/null +++ b/src/borg/cockpit/screens.py @@ -0,0 +1,91 @@ +""" +Borg Cockpit - the screens, one per kind of borg command. + +All screens have the same layout: the header, the logo panel next to a status panel (the part that +depends on the command), the log panel and the footer. +""" + +from textual.app import ComposeResult +from textual.containers import Container, Horizontal +from textual.screen import Screen +from textual.widgets import Footer, Header + +from .widgets import CreateStatusPanel, ExtractStatusPanel, GenericStatusPanel, LogoPanel, StandardLog + + +class CockpitScreen(Screen): + """The common layout; PANEL is the status panel class of the screen.""" + + PANEL = GenericStatusPanel + + def compose(self) -> ComposeResult: + yield Header(show_clock=True) + + with Container(id="main-grid"): + with Horizontal(id="top-row"): + yield LogoPanel(id="logopanel") + yield self.PANEL(id="status") + + yield StandardLog(id="standard-log") + + yield Footer() + + def on_mount(self) -> None: + # the top row is as high as the status panel needs, plus the border of the row. + self.query_one("#top-row").styles.height = self.PANEL.HEIGHT + 2 + self.query_one("#logo").styles.animate("opacity", 1, duration=1) + self.query_one("#slogan").styles.animate("opacity", 1, duration=1) + + def refresh_from_session(self, session) -> None: + """Show the current state of the session.""" + self.query_one("#status").update_from_session(session) + lines, dropped = session.drain() + self.query_one("#standard-log").add_lines(lines, dropped) + + def sample_speed(self, session) -> None: + """Called once per second, after Session.sample(): update the speed display.""" + self.query_one("#status").update_speed(session) + + def refresh_ui_labels(self) -> None: + """Redo the labels with the current translation.""" + self.query_one("#status").refresh_ui_labels() + self.query_one("#standard-log").update_title() + self.query_one("#slogan").update_slogan() + + def fade_out(self) -> None: + """Fade the logo out, for the exit.""" + self.query_one("#logo").styles.animate("opacity", 0, duration=2) + self.query_one("#slogan").styles.animate("opacity", 0, duration=2) + + +class CreateScreen(CockpitScreen): + """create, import-tar, recreate, transfer: the statistics of the archive being created.""" + + PANEL = CreateStatusPanel + + +class ExtractScreen(CockpitScreen): + """extract, export-tar: a progress bar over the bytes to extract.""" + + PANEL = ExtractStatusPanel + + +class GenericScreen(CockpitScreen): + """All other commands: the phases borg reports progress for.""" + + PANEL = GenericStatusPanel + + +SCREENS = { + "create": CreateScreen, + "import-tar": CreateScreen, + "recreate": CreateScreen, + "transfer": CreateScreen, + "extract": ExtractScreen, + "export-tar": ExtractScreen, +} + + +def screen_for_command(command): + """The screen class for a borg subcommand (None: unknown command).""" + return SCREENS.get(command, GenericScreen) diff --git a/src/borg/cockpit/session.py b/src/borg/cockpit/session.py new file mode 100644 index 0000000000..4a99ffe2c1 --- /dev/null +++ b/src/borg/cockpit/session.py @@ -0,0 +1,373 @@ +""" +Borg Cockpit - the state of one borg run. + +A Session is fed with the events the runner produces and is read by the widgets. It has no Textual +dependency, so it can be tested by replaying recorded JSON lines. All counting happens here and the +buffers are bounded, so that a flood of events (e.g. --list over millions of files) costs little more +than the JSON parsing; the widgets render what is in here at their own pace. +""" + +import json +import time +from collections import Counter, deque +from dataclasses import dataclass +from datetime import timedelta + +from ..helpers import format_file_size, format_timedelta +from .events import ( + ArchiveProgress, + ArchiveStatus, + FileStatus, + LogMessage, + ProcessFinished, + ProgressMessage, + ProgressPercent, + Question, + RawLine, + UnknownJson, +) + +# Python's getpass() prints this when it can not use a terminal (the runner starts borg without one) +# and falls back to reading the passphrase from stdin, which the cockpit does not support (yet). +# (The names avoid the word "pass", which makes bandit see hardcoded passwords in these messages.) +NO_TERMINAL_WARNING = "Warning: Password input may be echoed." +NO_TERMINAL_HINT = ( + "borg waits for a passphrase, but the cockpit can not enter one. " + "Quit, set BORG_PASSPHRASE, BORG_PASSCOMMAND or BORG_PASSPHRASE_FD and start again." +) + + +@dataclass +class Line: + """One line for the log panel.""" + + text: str + kind: str # "status": a --list line, tag is the status char. "archive": tag is kept / pruned / deleted / ... + # "log": tag is the level name. "raw", "hint". + tag: str = "" + + +@dataclass +class Phase: + """One progress operation of borg (progress_percent / progress_message), identified by its operation id.""" + + operation: int + msgid: str | None + message: str = "" + current: int | None = None + total: int | None = None + finished: bool = False + rate: float = 0.0 # increase of current per second, see Session.sample() + sampled_current: int | None = None # current at the previous Session.sample() + + @property + def fraction(self): + """Progress as 0.0 .. 1.0, None if unknown.""" + if not self.total or self.current is None: + return None + return min(max(self.current / self.total, 0.0), 1.0) + + +class Session: + LINES_MAX = 200 # log lines buffered between two drains, older lines are dropped (and counted) + + def __init__(self, command=None, capture_stdout=False): + """ + :param command: the borg subcommand that runs, e.g. "create" [None: unknown]. + :param capture_stdout: collect stdout instead of logging it: it carries the --json output, see final_json. + """ + self.command = command + self.capture_stdout = capture_stdout + self.stdout_lines = [] # the captured stdout lines + self.final_json = None # the --json output of borg (create, import-tar), parsed when borg has finished + self.started = time.monotonic() + self.finished_at = None + self.rc = None # exit code of borg, None while it runs + self.error = None # why borg could not be run, if so + self.archive_progress = None # the latest ArchiveProgress + self.archive_finished = False + # status char -> count of the --list lines. They only tell about the listing (which --filter reduces), + # the statistics of an archive being created never come from here, see nfiles and files_stats. + self.status_counts = Counter() + self.archive_counts = Counter() # status -> count, the archives listed by prune / delete / undelete + self.archives_dry_run = False # the archive_counts are what would be done + self.phases = {} # operation id -> Phase, in order of appearance + self._active_phase = None # operation id of the phase updated last + self.progress_text = "" # what borg works on right now: the current path or progress message + self.pending_question = None # the Question borg waits for an answer to + self.passphrase_needed = False + self.warnings = 0 # WARNING log messages + self.errors = 0 # ERROR and CRITICAL log messages + self._lines = deque(maxlen=self.LINES_MAX) + self._dropped = 0 + self._sample = (self.started, 0, 0, 0) # time, nfiles, original_size, deduplicated_size + self.files_per_second = 0.0 + self.original_bytes_per_second = 0.0 + self.deduplicated_bytes_per_second = 0.0 + + # derived values for the widgets + + @property + def running(self): + return self.rc is None + + @property + def elapsed(self): + """Seconds since the start of the run, frozen when it has finished.""" + end = time.monotonic() if self.finished_at is None else self.finished_at + return end - self.started + + @property + def final_stats(self): + """The archive statistics from the --json output, None until borg has finished (and only for some commands).""" + if not isinstance(self.final_json, dict): + return None + archive = self.final_json.get("archive") + # create --dry-run creates no archive and has its (reduced) stats at the top level. + stats = archive.get("stats") if isinstance(archive, dict) else self.final_json.get("stats") + return stats if isinstance(stats, dict) else None + + def _final_archive(self, key): + archive = self.final_json.get("archive") if isinstance(self.final_json, dict) else None + return archive.get(key) if isinstance(archive, dict) else None + + @property + def archive_name(self): + """The name of the created archive, from the --json output.""" + name = self._final_archive("name") + return name if isinstance(name, str) else None + + @property + def archive_duration(self): + """The duration of the archive creation [seconds], from the --json output.""" + duration = self._final_archive("duration") + return float(duration) if isinstance(duration, (int, float)) else None + + def _final_stat(self, key, types=int): + stats = self.final_stats + value = stats.get(key) if stats else None + return value if isinstance(value, types) and not isinstance(value, bool) else None + + # The statistics come from borg's statistics only: the ones of the final --json output (they also have + # the store statistics) are preferred over the latest archive_progress. That one is rate limited, so its + # numbers can be a little behind while borg runs; its final object has the final statistics. + # The --list lines are no source for them: they only exist if the user asked for the listing, and --filter + # reduces them to some status characters, so counting them would give wrong numbers. + # What borg does not tell is unknown: a dry-run only tells the number of files and the original size, + # and transfer has no files_stats. + + @property + def nfiles(self): + """Number of regular files processed, None if unknown (yet).""" + nfiles = self._final_stat("nfiles") + if nfiles is not None: + return nfiles + return None if self.archive_progress is None else self.archive_progress.nfiles + + @property + def files_stats(self): + """status char -> count of the items processed, empty if unknown (yet).""" + files_stats = self._final_stat("files_stats", dict) + if files_stats is not None: + return dict(files_stats) + return {} if self.archive_progress is None else dict(self.archive_progress.files_stats) + + def count(self, statuses): + """Number of items having one of the given status characters, see files_stats.""" + stats = self.files_stats + return sum(stats.get(status, 0) for status in statuses) + + @property + def original_size(self): + size = self._final_stat("original_size") + if size is not None: + return size + return None if self.archive_progress is None else self.archive_progress.original_size + + @property + def deduplicated_size(self): + size = self._final_stat("deduplicated_size") + if size is not None: + return size + return None if self.archive_progress is None else self.archive_progress.deduplicated_size + + @property + def active_phase(self): + """The unfinished phase that was updated last, None if there is none.""" + phase = self.phases.get(self._active_phase) + return None if phase is None or phase.finished else phase + + def phase(self, msgid): + """The phase with the given msgid (the last one, if there are several), None if there is none.""" + for phase in reversed(self.phases.values()): + if phase.msgid == msgid: + return phase + return None + + # feeding + + def feed(self, event): + """Update the state with one event from the runner.""" + match event: + case LogMessage(): + self._feed_log_message(event) + case FileStatus(): + self._add_status(event.status, event.path) + case ArchiveStatus(): + self.archive_counts[event.status] += 1 + self.archives_dry_run = event.dry_run + self._add_line(Line(event.message, "archive", event.status)) + case ArchiveProgress(): + self.archive_progress = event # the final object has the final statistics (and no path) + self.archive_finished = event.finished + self.progress_text = event.path or "" + case ProgressPercent() | ProgressMessage(): + self._feed_phase(event) + case Question(): + self._feed_question(event) + case RawLine(): + self._feed_raw_line(event) + case UnknownJson(): + self._add_line(Line(json.dumps(event.data), "raw", "stderr")) + case ProcessFinished(): + self.rc = event.rc + self.error = event.error + self.finished_at = time.monotonic() + self.pending_question = None + self.progress_text = "" + if event.error: + self._add_line(Line(event.error, "log", "ERROR")) + if self.stdout_lines: + self._parse_stdout() + + def _feed_log_message(self, event): + if event.levelname == "WARNING": + self.warnings += 1 + elif event.levelname in ("ERROR", "CRITICAL"): + self.errors += 1 + self._add_line(Line(event.message, "log", event.levelname)) + + def _add_status(self, status, path): + self.status_counts[status] += 1 + self._add_line(Line(f"{status} {path}", "status", status)) + + def _feed_phase(self, event): + phase = self.phases.get(event.operation) + if phase is None: + phase = self.phases[event.operation] = Phase(event.operation, event.msgid) + phase.finished = event.finished + if not event.finished: + phase.message = event.message + if isinstance(event, ProgressPercent): + phase.current = event.current + phase.total = event.total + self._active_phase = event.operation + self.progress_text = "" if event.finished else event.message + + def _feed_question(self, event): + if event.needs_answer: + self.pending_question = event + self._add_line(Line(event.message, "log", "PROMPT")) + else: + self.pending_question = None + self._add_line(Line(event.message, "log", "INFO")) + + def _feed_raw_line(self, event): + if event.stream == "stdout" and self.capture_stdout: + self.stdout_lines.append(event.line) + return + self._add_line(Line(event.line, "raw", event.stream)) + if event.stream == "stderr" and event.line == NO_TERMINAL_WARNING: + self.passphrase_needed = True + self._add_line(Line(NO_TERMINAL_HINT, "hint")) + + def _parse_stdout(self): + """The captured stdout is the --json output: keep it and log its statistics like --stats would.""" + try: + data = json.loads("\n".join(self.stdout_lines)) + except ValueError: + data = None + if isinstance(data, dict): + self.final_json = data + for text in self.final_stats_lines(): + self._add_line(Line(text, "log", "STATS")) + else: # not what we expected, show it as it is + for line in self.stdout_lines: + self._add_line(Line(line, "raw", "stdout")) + + def final_stats_lines(self): + """The statistics from the --json output as text lines, like the --stats output of borg.""" + lines = [] + name, fingerprint = self.archive_name, self._final_archive("id") + if name is not None: + lines.append(f"Archive name: {name}") + if isinstance(fingerprint, str): + lines.append(f"Archive fingerprint: {fingerprint}") + duration = self.archive_duration + if duration is not None: + lines.append(f"Duration: {format_timedelta(timedelta(seconds=duration))}") + if isinstance(self.final_json, dict) and self.final_json.get("dry_run"): + lines.append("Dry run: no archive was created.") + nfiles = self._final_stat("nfiles") + if nfiles is not None: + lines.append(f"Number of files: {nfiles}") + for key, label in (("original_size", "Original size"), ("deduplicated_size", "Deduplicated size")): + size = self._final_stat(key) + if size is not None: + lines.append(f"{label}: {format_file_size(size)}") + for key, label in (("hashing_time", "Time spent in hashing"), ("chunking_time", "Time spent in chunking")): + seconds = self._final_stat(key, (int, float)) + if seconds is not None: + lines.append(f"{label}: {format_timedelta(timedelta(seconds=seconds))}") + files_stats = self._final_stat("files_stats", dict) + if files_stats is not None: + for status, label in ( + ("A", "Added files"), + ("U", "Unchanged files"), + ("M", "Modified files"), + ("E", "Error files"), + ("C", "Files changed while reading"), + ): + lines.append(f"{label}: {files_stats.get(status, 0)}") + store_stats = self._final_stat("store_stats", dict) + if store_stats: + from ..archive import format_store_stats + + lines.extend(format_store_stats(store_stats).splitlines()) + return lines + + def _add_line(self, line): + if len(self._lines) == self._lines.maxlen: + self._dropped += 1 + self._lines.append(line) + + def drain(self): + """Take the buffered log lines: (lines, number of older lines dropped since the previous drain).""" + lines, dropped = list(self._lines), self._dropped + self._lines.clear() + self._dropped = 0 + return lines, dropped + + def sample(self, now=None): + """Compute the rates (files/s, bytes/s, progress of the phases) since the previous sample() call.""" + now = time.monotonic() if now is None else now + then, nfiles, original_size, deduplicated_size = self._sample + dt = now - then + if dt <= 0: + return + if not self.running: # nothing moves anymore + self.files_per_second = self.original_bytes_per_second = self.deduplicated_bytes_per_second = 0.0 + for phase in self.phases.values(): + phase.rate = 0.0 + return + current = (self.nfiles or 0, self.original_size or 0, self.deduplicated_size or 0) + self.files_per_second = max(current[0] - nfiles, 0) / dt + self.original_bytes_per_second = max(current[1] - original_size, 0) / dt + self.deduplicated_bytes_per_second = max(current[2] - deduplicated_size, 0) / dt + self._sample = (now, *current) + for phase in self.phases.values(): + if phase.finished or phase.current is None: + phase.rate = 0.0 + elif phase.sampled_current is not None: + phase.rate = max(phase.current - phase.sampled_current, 0) / dt + phase.sampled_current = phase.current diff --git a/src/borg/cockpit/translator.py b/src/borg/cockpit/translator.py index 2302d451c4..28fb51faa3 100644 --- a/src/borg/cockpit/translator.py +++ b/src/borg/cockpit/translator.py @@ -12,6 +12,18 @@ "Other: ": "Other: ", "Errors: ": "Escaped: ", "RC: ": "Termination Code: ", + "Speed: ": "Assimilation rate: ", + "Original: ": "Raw biomass: ", + "Deduplicated: ": "Assimilated biomass: ", + "Progress: ": "Assimilating: ", + "Warnings: ": "Anomalies: ", + "Archive: ": "Collective: ", + "Archives: ": "Collectives: ", + "Extracted: ": "Released: ", + "Items: ": "Entities: ", + "Included: ": "Selected: ", + "Excluded: ": "Irrelevant: ", + "Phases": "Stages", "Log": "Subspace Transmissions", } diff --git a/src/borg/cockpit/widgets.py b/src/borg/cockpit/widgets.py index 4aef72e88f..3c0785f72c 100644 --- a/src/borg/cockpit/widgets.py +++ b/src/borg/cockpit/widgets.py @@ -3,26 +3,149 @@ """ import random +import re import time +from datetime import timedelta from rich.markup import escape +from rich.text import Text from textual.app import ComposeResult -from textual.reactive import reactive -from textual.widgets import Static, RichLog +from textual.widgets import ProgressBar, RichLog, Static from textual.containers import Vertical, Container -from ..helpers import classify_ec +from ..helpers import classify_ec, format_file_size, format_timedelta +from ..helpers.parseformat import ellipsis_truncate from .translator import T, TRANSLATOR +# The control characters (C0, DEL, C1). Text from borg (paths, archive names, messages) can contain them, +# e.g. an ESC starting a terminal escape sequence, and the terminal would interpret them. +CONTROL_CHARS = {code: "\ufffd" for code in (*range(0x20), *range(0x7F, 0xA0))} +CONTROL_CHARS_MULTILINE = {code: char for code, char in CONTROL_CHARS.items() if code not in (0x09, 0x0A)} -class StatusPanel(Static): - elapsed_time = reactive(0.0, init=False) - files_count = reactive(0, init=False) # unchanged + modified + added + other + error - unchanged_count = reactive(0, init=False) - modified_count = reactive(0, init=False) - added_count = reactive(0, init=False) - other_count = reactive(0, init=False) - error_count = reactive(0, init=False) - rc = reactive(None, init=False) + +def printable(text, multiline=False): + """ + with its control characters replaced by U+FFFD, so that showing it can not affect the terminal. + + :param multiline: keep linefeeds and tabs, for text that may have more than one line. + """ + return text.translate(CONTROL_CHARS_MULTILINE if multiline else CONTROL_CHARS) + + +class StatusPanelBase(Static): + """ + Base class of the panels showing the numbers of a borg run, next to the logo. + + Subclasses compose their lines (Static widgets with an id) and implement show_session(), which + shows the state of a Session in them; HEIGHT is the number of lines they need, the screen sizes + the top row accordingly. A line is only updated when its text changes. + + The lines show text that comes from borg (paths, archive names, messages), so they never + interpret their content as markup: any text must be shown as it is, except for control + characters, see printable(). + """ + + HEIGHT = 0 + + def __init__(self, *args, **kwargs): + super().__init__(*args, **kwargs) + self.session = None + self.shown = {} # widget id -> text currently shown + + @staticmethod + def _line(widget_id, label, value="", classes="status"): + """A Static for one "Label: value" line, for compose().""" + return Static(T(label) + value, classes=classes, id=widget_id, markup=False) + + def show(self, widget_id, text): + """Show (a str or a rich Text) in the widget with , if it is not shown already.""" + if self.shown.get(widget_id) != text: + self.shown[widget_id] = text + self.query_one(f"#{widget_id}").update(text) + + def show_value(self, widget_id, label, value, truncate=False): + """Show a translated label and a value; long values can be truncated to the panel width, so they don't wrap.""" + label = T(label) + value = printable(str(value)) + if truncate and value: + space = (self.size.width or 60) - len(label) - 1 + value = ellipsis_truncate(value, space).rstrip() + self.show(widget_id, label + value) + + def update_from_session(self, session): + """Show the current state of the session.""" + self.session = session + self.show_session(session) + + def show_session(self, session): + raise NotImplementedError + + def update_speed(self, session): + """Called once per second, after Session.sample(): update the speed display, if the panel has one.""" + + def show_speed(self, session): + """Show the current rates, if the panel has a speed display.""" + + def refresh_ui_labels(self): + """Redo all lines with the current translation.""" + self.shown.clear() + if self.session is not None: + self.show_session(self.session) + self.show_speed(self.session) + + # lines most panels have + + @staticmethod + def _format_size(size): + return "-" if size is None else format_file_size(size) + + @staticmethod + def _format_count(count): + return "-" if count is None else str(count) + + def show_elapsed(self, session): + if TRANSLATOR.enabled: + # There seems to be no official formula for stardates, so we make something up. + # When showing the stardate, it is an absolute time, not relative "elapsed time". + ut = time.time() + sd = (ut - 1735689600) / 60.0 # Minutes since 2025-01-01 00:00.00 UTC + self.show("status-elapsed", f"Stardate {sd:.1f}") + else: + seconds = int(session.elapsed) + days, seconds = divmod(seconds, 86400) + h, m, s = seconds // 3600, (seconds % 3600) // 60, seconds % 60 + self.show("status-elapsed", f"Elapsed: {days:02d}d {h:02d}:{m:02d}:{s:02d}") + + def show_count(self, widget_id, label, count): + """Show a count that is fine when zero (or unknown: None) and a warning otherwise.""" + widget = self.query_one(f"#{widget_id}") + widget.set_class(not count, "errors-ok") + widget.set_class(bool(count), "errors-warning") + self.show_value(widget_id, label, self._format_count(count)) + + def show_warnings(self, session): + self.show_count("status-warnings", "Warnings: ", session.warnings + session.errors) + + def show_activity(self, session): + """What borg works on right now.""" + self.show_value("status-activity", "Progress: ", session.progress_text, truncate=True) + + def show_rc(self, session): + rc = session.rc + if rc is None: + self.show("status-rc", T("RC: ") + "RUNNING") + return + status = classify_ec(rc) + widget = self.query_one("#status-rc") + widget.set_class(status == "success", "rc-ok") + widget.set_class(status == "warning", "rc-warning") + widget.set_class(status not in ("success", "warning"), "rc-error") # error, signal + self.show("status-rc", T("RC: ") + str(rc)) + + +class CreateStatusPanel(StatusPanelBase): + """create, import-tar, recreate, transfer: the statistics of the archive being created.""" + + HEIGHT = 17 # sparkline (4), speed (1), 12 lines def __init__(self, *args, **kwargs): super().__init__(*args, **kwargs) @@ -31,154 +154,229 @@ def __init__(self, *args, **kwargs): def compose(self) -> ComposeResult: with Vertical(): yield SpeedSparkline(self.speed_history, id="speed-sparkline") - yield Static(T("Speed: 0/s"), id="status-speed") + yield self._line("status-speed", "Speed: ", "0 files/s", classes="") with Vertical(id="statuses"): - yield Static(T("Elapsed: 00d 00:00:00"), classes="status", id="status-elapsed") - yield Static(T("Files: 0"), classes="status", id="status-files") - yield Static(T("Unchanged: 0"), classes="status", id="status-unchanged") - yield Static(T("Modified: 0"), classes="status", id="status-modified") - yield Static(T("Added: 0"), classes="status", id="status-added") - yield Static(T("Other: 0"), classes="status", id="status-other") - yield Static(T("Errors: 0"), classes="status error-ok", id="status-errors") - yield Static(T("RC: RUNNING"), classes="status", id="status-rc") - - def update_speed(self, kfiles_per_second: float): - self.speed_history.append(kfiles_per_second) + yield self._line("status-elapsed", "Elapsed: ", "00d 00:00:00") + yield self._line("status-files", "Files: ", "-") + yield self._line("status-original", "Original: ", "-") + yield self._line("status-deduplicated", "Deduplicated: ", "-") + yield self._line("status-unchanged", "Unchanged: ", "-") + yield self._line("status-modified", "Modified: ", "-") + yield self._line("status-added", "Added: ", "-") + yield self._line("status-other", "Other: ", "-") + yield self._line("status-errors", "Errors: ", "-", classes="status errors-ok") + yield self._line("status-warnings", "Warnings: ", "0", classes="status errors-ok") + yield self._line("status-activity", "Progress: ") + yield self._line("status-rc", "RC: ", "RUNNING") + + def show_session(self, session): + self.show_elapsed(session) + self.show_value("status-files", "Files: ", self._format_count(session.nfiles)) + original, deduplicated = session.original_size, session.deduplicated_size + self.show_value("status-original", "Original: ", self._format_size(original)) + ratio = f" ({deduplicated * 100 / original:.1f}%)" if deduplicated is not None and original else "" + self.show_value("status-deduplicated", "Deduplicated: ", self._format_size(deduplicated) + ratio) + # the counts by status are unknown (shown as "-") while borg does not tell them: transfer has none, + # neither has a dry-run. They are borg's statistics, not the counts of the --list lines. + stats = session.files_stats + unchanged, modified, added, errors = (session.count(status) if stats else None for status in "UMAE") + other = sum(stats.values()) - unchanged - modified - added - errors if stats else None + self.show_value("status-unchanged", "Unchanged: ", self._format_count(unchanged)) + self.show_value("status-modified", "Modified: ", self._format_count(modified)) + self.show_value("status-added", "Added: ", self._format_count(added)) + self.show_value("status-other", "Other: ", self._format_count(other)) + self.show_count("status-errors", "Errors: ", errors) + self.show_warnings(session) + if not session.running and session.archive_name is not None: + # the final --json output tells about the archive that was created. + duration = session.archive_duration + value = session.archive_name + if duration is not None: + value += f" ({format_timedelta(timedelta(seconds=duration))})" + self.show_value("status-activity", "Archive: ", value, truncate=True) + else: + self.show_activity(session) + self.show_rc(session) + + def update_speed(self, session): + self.speed_history.append(session.files_per_second) self.speed_history = self.speed_history[-SpeedSparkline.HISTORY_SIZE :] - # Use our custom update method self.query_one("#speed-sparkline").update_data(self.speed_history) - self.query_one("#status-speed").update(T(f"Speed: {int(kfiles_per_second * 1000)}/s")) + self.show_speed(session) - def watch_error_count(self, count: int) -> None: - sw = self.query_one("#status-errors") - if count == 0: - sw.remove_class("errors-warning") - sw.add_class("errors-ok") - else: - sw.remove_class("errors-ok") - sw.add_class("errors-warning") - sw.update(T(f"Errors: {count}")) + def show_speed(self, session): + rates = f"{session.files_per_second:.0f} files/s, {format_file_size(session.original_bytes_per_second)}/s" + self.show("status-speed", T("Speed: ") + rates) - def watch_files_count(self, count: int) -> None: - self.query_one("#status-files").update(T(f"Files: {count}")) - def watch_unchanged_count(self, count: int) -> None: - self.query_one("#status-unchanged").update(T(f"Unchanged: {count}")) +class ExtractStatusPanel(StatusPanelBase): + """extract, export-tar: a progress bar over the bytes to extract, and the counts of the --list lines.""" - def watch_modified_count(self, count: int) -> None: - self.query_one("#status-modified").update(T(f"Modified: {count}")) + HEIGHT = 14 # sparkline (4), speed (1), progress bar (1), 8 lines + PHASE = "extract" # the msgid of the progress operation the bar shows - def watch_added_count(self, count: int) -> None: - self.query_one("#status-added").update(T(f"Added: {count}")) + def __init__(self, *args, **kwargs): + super().__init__(*args, **kwargs) + self.speed_history = [0.0] * SpeedSparkline.HISTORY_SIZE - def watch_other_count(self, count: int) -> None: - self.query_one("#status-other").update(T(f"Other: {count}")) + def compose(self) -> ComposeResult: + with Vertical(): + yield SpeedSparkline(self.speed_history, id="speed-sparkline") + yield self._line("status-speed", "Speed: ", "0 B/s", classes="") + yield ProgressBar(id="extract-bar") # indeterminate until the total is known - def watch_rc(self, rc: int): - label = self.query_one("#status-rc") - if rc is None: - label.update(T("RC: RUNNING")) - return + with Vertical(id="statuses"): + yield self._line("status-extracted", "Extracted: ", "-") + yield self._line("status-elapsed", "Elapsed: ", "00d 00:00:00") + yield self._line("status-items", "Items: ", "0") + yield self._line("status-included", "Included: ", "0") + yield self._line("status-excluded", "Excluded: ", "0") + yield self._line("status-warnings", "Warnings: ", "0", classes="status errors-ok") + yield self._line("status-activity", "Progress: ") + yield self._line("status-rc", "RC: ", "RUNNING") + + def show_session(self, session): + phase = session.phase(self.PHASE) + bar = self.query_one("#extract-bar") + extracted = "-" + if phase is not None and phase.total: + current = phase.total if phase.finished else min(phase.current or 0, phase.total) + bar.update(total=phase.total, progress=current) + extracted = f"{format_file_size(current)} / {format_file_size(phase.total)}" + elif phase is not None and phase.finished: # there was nothing to extract + bar.update(total=1, progress=1) + self.show_value("status-extracted", "Extracted: ", extracted) + self.show_elapsed(session) + self.show_value("status-items", "Items: ", sum(session.status_counts.values())) + self.show_value("status-included", "Included: ", session.status_counts.get("+", 0)) + self.show_value("status-excluded", "Excluded: ", session.status_counts.get("-", 0)) + self.show_warnings(session) + self.show_activity(session) + self.show_rc(session) + + def _rate(self, session): + phase = session.phase(self.PHASE) + return 0.0 if phase is None else phase.rate + + def update_speed(self, session): + self.speed_history.append(self._rate(session)) + self.speed_history = self.speed_history[-SpeedSparkline.HISTORY_SIZE :] + self.query_one("#speed-sparkline").update_data(self.speed_history) + self.show_speed(session) - label.remove_class("rc-ok") - label.remove_class("rc-warning") - label.remove_class("rc-error") + def show_speed(self, session): + self.show("status-speed", T("Speed: ") + f"{format_file_size(self._rate(session))}/s") - status = classify_ec(rc) - if status == "success": - label.add_class("rc-ok") - elif status == "warning": - label.add_class("rc-warning") - else: # error, signal - label.add_class("rc-error") - label.update(T(f"RC: {rc}")) +class GenericStatusPanel(StatusPanelBase): + """All other commands: elapsed time, warnings, exit code and the phases borg reports progress for.""" - def watch_elapsed_time(self, elapsed: float) -> None: - if TRANSLATOR.enabled: - # There seems to be no official formula for stardates, so we make something up. - # When showing the stardate, it is an absolute time, not relative "elapsed time". - ut = time.time() - sd = (ut - 1735689600) / 60.0 # Minutes since 2025-01-01 00:00.00 UTC - msg = f"Stardate {sd:.1f}" - else: - seconds = int(elapsed) - days, seconds = divmod(seconds, 86400) - h, m, s = seconds // 3600, (seconds % 3600) // 60, seconds % 60 - msg = f"Elapsed: {days:02d}d {h:02d}:{m:02d}:{s:02d}" - self.query_one("#status-elapsed").update(msg) + HEIGHT = 17 # 4 lines, the title, PHASE_LINES + PHASE_LINES = 12 # the phases shown (the last ones, if there are more) + BAR_WIDTH = 10 + PERCENTAGE = re.compile(r"\s*\d+(\.\d+)?%$") # the percentage at the end of a progress message - def refresh_ui_labels(self): - """Update static UI labels with current translation.""" - self.watch_elapsed_time(self.elapsed_time) - self.query_one("#status-files").update(T(f"Files: {self.files_count}")) - self.query_one("#status-unchanged").update(T(f"Unchanged: {self.unchanged_count}")) - self.query_one("#status-modified").update(T(f"Modified: {self.modified_count}")) - self.query_one("#status-added").update(T(f"Added: {self.added_count}")) - self.query_one("#status-other").update(T(f"Other: {self.other_count}")) - self.query_one("#status-errors").update(T(f"Errors: {self.error_count}")) - - if self.rc is not None: - self.watch_rc(self.rc) - else: - self.query_one("#status-rc").update(T("RC: RUNNING")) + def compose(self) -> ComposeResult: + with Vertical(): + with Vertical(id="statuses"): + yield self._line("status-elapsed", "Elapsed: ", "00d 00:00:00") + yield self._line("status-warnings", "Warnings: ", "0", classes="status errors-ok") + yield self._line("status-archives", "Archives: ", "-") + yield self._line("status-rc", "RC: ", "RUNNING") + yield Static(T("Phases"), classes="panel-title", id="phases-title") + yield Static("", id="phases", markup=False) + + def show_session(self, session): + self.show_elapsed(session) + self.show_warnings(session) + counts = session.archive_counts + statuses = [status for status in ("kept", "pruned", "deleted", "undeleted") if counts[status]] + statuses += [status for status in counts if status not in statuses] + parts = [f"{counts[status]} {status}" for status in statuses] + dry_run = " (dry-run)" if session.archives_dry_run else "" + self.show_value("status-archives", "Archives: ", ", ".join(parts) + dry_run if parts else "-") + self.show_rc(session) + self.show("phases-title", T("Phases")) + space = (self.size.width or 60) - self.BAR_WIDTH - 3 + lines = [] # rich Text objects, so that the messages are not interpreted as markup + for phase in list(session.phases.values())[-self.PHASE_LINES :]: + if phase.finished: + mark, filled, style = "✔", self.BAR_WIDTH, "green" + else: + fraction = phase.fraction + mark, filled, style = "▶", 0 if fraction is None else round(fraction * self.BAR_WIDTH), "bold white" + bar = "█" * filled + "░" * (self.BAR_WIDTH - filled) + message = printable(phase.message or phase.msgid or "") + if phase.finished: # the last percentage borg reported before finishing is not the final one + message = self.PERCENTAGE.sub("", message) + text = ellipsis_truncate(message, space).rstrip() + lines.append(Text(f"{mark} {bar} {text}", style=style)) + self.show("phases", Text("\n").join(lines)) class StandardLog(Vertical): + """The log panel: log messages, --list lines and everything else borg outputs.""" + + # Styles for the --list status characters, see "Item flags" in the borg create help. + STATUS_STYLES = { + "E": "red", # error + "C": "yellow", # regular file, changed while reading + "?": "red", # missing status, a bug + "A": "white", # added regular file (cache miss, slow!) + "M": "white", # modified regular file (cache hit, but different, slow!) + "U": "green", # unchanged regular file (cache hit) + "-": "white", # excluded + "x": "white", # skipped (dataless) + } + DEFAULT_STATUS_STYLE = "green" # d, b, c, h, s, f, i: metadata only. +: included. + # Styles for the log levels (and the prompts and the final statistics). + LEVEL_STYLES = { + "DEBUG": "dim", + "WARNING": "yellow", + "ERROR": "red", + "CRITICAL": "bold red", + "PROMPT": "bold yellow", + "STATS": "bold", + } + MAX_LINES = 5000 # lines kept for scrolling back + def compose(self) -> ComposeResult: yield Static(T("Log"), classes="panel-title", id="standard-log-title") - yield RichLog(id="standard-log-content", highlight=False, markup=True, auto_scroll=True, max_lines=None) + yield RichLog( + id="standard-log-content", highlight=False, markup=False, auto_scroll=True, max_lines=self.MAX_LINES + ) def update_title(self): self.query_one("#standard-log-title").update(T("Log")) - def add_line(self, line: str): - # TODO: make this more generic, use json output from borg. - # currently, this is only really useful for borg create/extract --list - line = line.rstrip() - if len(line) == 0: + @classmethod + def style_for(cls, line): + """The rich style for a Line from the Session, None for plain text.""" + if line.kind == "status": + return cls.STATUS_STYLES.get(line.tag, cls.DEFAULT_STATUS_STYLE) + if line.kind == "archive": + return "green" if line.tag in ("kept", "undeleted") else "white" # the archive stays / is back + if line.kind == "log": + return cls.LEVEL_STYLES.get(line.tag) + if line.kind == "hint": + return "bold yellow" + return None + + def add_lines(self, lines, dropped=0): + """ + Append the lines taken from Session.drain(); dropped lines are only mentioned. + + The lines are written as rich Text objects: their text comes from borg (paths, messages) and + must be shown as it is, not interpreted as markup. Control characters are replaced, see printable(). + """ + if not lines and not dropped: return - - markup_tag = None - if len(line) >= 2: - if line[1] == " " and line[0] in "EAMUdcbs+-": - # looks like from borg create/extract --list - status_panel = self.app.query_one("#status") - status_panel.files_count += 1 - status = line[0] - match status: - case "E": - status_panel.error_count += 1 - case "U" | "-": - status_panel.unchanged_count += 1 - case "M": - status_panel.modified_count += 1 - case "A" | "+": - status_panel.added_count += 1 - case "d" | "c" | "b" | "s": - status_panel.other_count += 1 - - markup_tag = { - "E": "red", # Error - "A": "white", # Added regular file (cache miss, slow!) - "M": "white", # Modified regular file (cache hit, but different, slow!) - "U": "green", # Updated regular file (cache hit) - "d": "green", # directory - "c": "green", # char device - "b": "green", # block device - "s": "green", # socket - "-": "white", # excluded - "+": "green", # included - }.get(status) - log_widget = self.query_one("#standard-log-content") - - safe_line = escape(line) - if markup_tag: - safe_line = f"[{markup_tag}]{safe_line}[/]" - - log_widget.write(safe_line) + if dropped: + log_widget.write(Text(f"... {dropped} more lines not shown ...", style="dim")) + for line in lines: + log_widget.write(Text(printable(line.text, multiline=True), style=self.style_for(line) or "")) class Starfield(Static): diff --git a/src/borg/testsuite/archive_test.py b/src/borg/testsuite/archive_test.py index f98d3e1616..5dabc9f4e3 100644 --- a/src/borg/testsuite/archive_test.py +++ b/src/borg/testsuite/archive_test.py @@ -170,8 +170,10 @@ def test_stats_progress_json(stats): assert isinstance(result["time"], float) assert result["finished"] is True # see #6570 assert "path" not in result - assert "original_size" not in result - assert "nfiles" not in result + # the final object has the final statistics + assert result["original_size"] == 20 + assert result["deduplicated_size"] == 20 + assert result["nfiles"] == 1 def test_stats_as_dict(stats): diff --git a/src/borg/testsuite/archiver/create_cmd_test.py b/src/borg/testsuite/archiver/create_cmd_test.py index b94569ee51..c1695d1335 100644 --- a/src/borg/testsuite/archiver/create_cmd_test.py +++ b/src/borg/testsuite/archiver/create_cmd_test.py @@ -739,6 +739,41 @@ def test_progress_on(archivers, request): assert "0 B O 0 B U 0 N" in output +def test_progress_json_final_statistics(archivers, request): + archiver = request.getfixturevalue(archivers) + create_regular_file(archiver.input_path, "file1", size=1024 * 80) + create_regular_file(archiver.input_path, "file2", size=1024) + cmd(archiver, "repo-create", RK_ENCRYPTION) + output = cmd(archiver, "create", "test", "input", "--progress", "--log-json") + messages = [json.loads(line) for line in output.splitlines() if line.startswith("{")] + final = [msg for msg in messages if msg["type"] == "archive_progress"][-1] + # the progress is rate limited, so only the final object tells about everything that was processed. + assert final["finished"] and "path" not in final + assert final["nfiles"] == 2 and final["original_size"] == 1024 * 81 + assert final["files_stats"] == {"A": 2, "d": 1} + + +def test_progress_dry_run(archivers, request, monkeypatch): + archiver = request.getfixturevalue(archivers) + monkeypatch.setenv("BORG_PROGRESS_FPS", "1000000") # no rate limit: the progress is reported after each item + create_regular_file(archiver.input_path, "file1", size=1024 * 80) + create_regular_file(archiver.input_path, "dir/file2", size=1024) + cmd(archiver, "repo-create", RK_ENCRYPTION) + output = cmd(archiver, "create", "--dry-run", "test", "input", "--progress", "--log-json") + messages = [json.loads(line) for line in output.splitlines() if line.startswith("{")] + progress = [msg for msg in messages if msg["type"] == "archive_progress"] + # a dry-run reports what would be backed up: the files and their size. it can not know what is new. + assert [msg["nfiles"] for msg in progress] == [1, 2, 2] + assert sorted(msg["path"] for msg in progress[:-1]) == ["input/dir/file2", "input/file1"] + final = progress[-1] + assert final["finished"] and "path" not in final + assert final["original_size"] == 1024 * 81 and "deduplicated_size" not in final + # the text progress works also + output = cmd(archiver, "create", "--dry-run", "test", "input", "--progress") + assert "82.94 kB O 0 B U 2 N input/" in output + assert not cmd(archiver, "repo-list") # still no archive + + def test_progress_off(archivers, request): archiver = request.getfixturevalue(archivers) create_regular_file(archiver.input_path, "file1", size=1024 * 80) diff --git a/src/borg/testsuite/archiver/delete_cmd_test.py b/src/borg/testsuite/archiver/delete_cmd_test.py index e90d324e44..749660c445 100644 --- a/src/borg/testsuite/archiver/delete_cmd_test.py +++ b/src/borg/testsuite/archiver/delete_cmd_test.py @@ -2,6 +2,8 @@ from ...constants import * # NOQA from ...helpers import CommandError +import json + from . import cmd, create_regular_file, generate_archiver_tests, RK_ENCRYPTION pytest_generate_tests = lambda metafunc: generate_archiver_tests(metafunc, kinds="local,binary") # NOQA @@ -135,3 +137,25 @@ def test_delete_name_and_match_archives_are_combined(archivers, request, monkeyp cmd(archiver, "delete", "home", "-a", "host:host1") output = cmd(archiver, "repo-list", "--format={hostname}{NL}") assert output.strip() == "host2" + + +def test_delete_list_json(archivers, request): + archiver = request.getfixturevalue(archivers) + create_regular_file(archiver.input_path, "file1", size=1024 * 80) + cmd(archiver, "repo-create", RK_ENCRYPTION) + cmd(archiver, "create", "test1", "input") + cmd(archiver, "create", "test2", "input") + # with --log-json, the listing consists of archive_status objects (one per archive), no text lines + output = cmd(archiver, "delete", "--dry-run", "--list", "--log-json", "-a", "sh:test*") + messages = [json.loads(line) for line in output.splitlines()] + statuses = [msg for msg in messages if msg["type"] == "archive_status"] + assert {(msg["name"], msg["status"]) for msg in statuses} == {("test1", "deleted"), ("test2", "deleted")} + for msg in statuses: + assert msg["message"].startswith("Would delete: ") and msg["name"] in msg["message"] + assert msg["dry_run"] is True # the status is what would be done + assert msg["archive"] == msg["name"] and len(msg["id"]) == 64 and "T" in msg["time"] + output = cmd(archiver, "delete", "--list", "--log-json", "test1") + statuses = [msg for msg in map(json.loads, output.splitlines()) if msg["type"] == "archive_status"] + assert [(msg["name"], msg["status"], msg["dry_run"]) for msg in statuses] == [("test1", "deleted", False)] + assert statuses[0]["message"].startswith("Deleted archive: ") and statuses[0]["message"].endswith("(1/1)") + assert "test1" not in cmd(archiver, "repo-list") diff --git a/src/borg/testsuite/archiver/extract_cmd_test.py b/src/borg/testsuite/archiver/extract_cmd_test.py index ac102f4705..9b7700ea3b 100644 --- a/src/borg/testsuite/archiver/extract_cmd_test.py +++ b/src/borg/testsuite/archiver/extract_cmd_test.py @@ -1,5 +1,6 @@ import errno import io +import json import os from pathlib import Path import shutil @@ -1256,3 +1257,21 @@ def close(self): out = _extract_with_raw_file_class(archiver, BadCloseRaw, BackupIOError) assert f"input/file1: close: [Errno {errno.EIO}] Input/output error" in out assert os.path.getsize("output/input/file1") == 1024 # the content was written completely + + +def test_extract_list_json(archivers, request): + archiver = request.getfixturevalue(archivers) + cmd(archiver, "repo-create", RK_ENCRYPTION) + create_regular_file(archiver.input_path, "file1", size=1024) + create_regular_file(archiver.input_path, "file2", size=1024) + cmd(archiver, "create", "test", "input") + + with changedir("output"): + output = cmd(archiver, "extract", "test", "--list", "--log-json", "-e", "input/file2") + # with --log-json, the listing consists of file_status objects (one per item), no text lines + messages = [json.loads(line) for line in output.splitlines()] + file_status = [msg for msg in messages if msg["type"] == "file_status"] + assert {"type": "file_status", "status": "+", "path": "input"} in file_status + assert {"type": "file_status", "status": "+", "path": "input/file1"} in file_status + assert {"type": "file_status", "status": "-", "path": "input/file2"} in file_status + assert len(file_status) == 3 diff --git a/src/borg/testsuite/archiver/prune_cmd_test.py b/src/borg/testsuite/archiver/prune_cmd_test.py index e101d4cd1a..e1163adc75 100644 --- a/src/borg/testsuite/archiver/prune_cmd_test.py +++ b/src/borg/testsuite/archiver/prune_cmd_test.py @@ -1074,3 +1074,34 @@ def test_prune_group_by_invalid_key(archivers, request): cmd(archiver, "repo-create", RK_ENCRYPTION) output = cmd(archiver, "prune", "--group-by", "bogus", "--keep-daily=1", exit_code=2) assert "Invalid group-by key: bogus" in output + + +def test_prune_list_json(archivers, request, backup_files): + archiver = request.getfixturevalue(archivers) + cmd(archiver, "repo-create", RK_ENCRYPTION) + cmd(archiver, "create", "test1", backup_files) + cmd(archiver, "create", "test2", backup_files) + # with --log-json, the listing consists of archive_status objects (one per listed archive), no text lines + output = prune_ungrouped(archiver, "--list", "--dry-run", "--keep-daily=1", "--log-json") + messages = [json.loads(line) for line in output.splitlines()] + statuses = {msg["name"]: msg for msg in messages if msg["type"] == "archive_status"} + assert set(statuses) == {"test1", "test2"} + pruned, kept = statuses["test1"], statuses["test2"] + assert pruned["status"] == "pruned" and kept["status"] == "kept" + assert pruned["dry_run"] is True and kept["dry_run"] is True # the status is what would be done + assert pruned["kept"] is False and pruned["deleted_archive_number"] == 1 + assert pruned["message"].startswith("Would prune:") and "test1" in pruned["message"] + assert kept["kept"] is True and kept["keep_rule"] == "daily" and kept["kept_oldest"] is False + assert kept["kept_archive_number"] == 1 + assert kept["message"].startswith("Keeping archive (rule: daily #1):") and "test2" in kept["message"] + for status in statuses.values(): + assert status["archive"] == status["name"] and len(status["id"]) == 64 and "T" in status["time"] + assert status["group"] == {} # grouping is switched off by prune_ungrouped() + # --list-pruned lists the pruned archives only, and it really prunes without --dry-run + output = prune_ungrouped(archiver, "--list-pruned", "--keep-daily=1", "--log-json") + messages = [json.loads(line) for line in output.splitlines()] + statuses = [msg for msg in messages if msg["type"] == "archive_status"] + assert [(msg["name"], msg["status"], msg["kept"]) for msg in statuses] == [("test1", "pruned", False)] + assert statuses[0]["dry_run"] is False + assert statuses[0]["message"].startswith("Pruning archive (1/1):") + assert "test1" not in cmd(archiver, "repo-list") diff --git a/src/borg/testsuite/archiver/recreate_cmd_test.py b/src/borg/testsuite/archiver/recreate_cmd_test.py index af140f7691..ec0476cbc5 100644 --- a/src/borg/testsuite/archiver/recreate_cmd_test.py +++ b/src/borg/testsuite/archiver/recreate_cmd_test.py @@ -331,6 +331,68 @@ def test_recreate_list_output(archivers, request): assert "- input/file5" not in output +def test_recreate_progress_json(archivers, request): + archiver = request.getfixturevalue(archivers) + cmd(archiver, "repo-create", RK_ENCRYPTION) + create_regular_file(archiver.input_path, "file1", size=1024) + create_regular_file(archiver.input_path, "file2", size=1024) + cmd(archiver, "create", "test", "input") + output = cmd(archiver, "recreate", "-a", "test", "--log-json", "--progress", "-e", "input/file2") + lines = output.splitlines() + messages = [json.loads(line) for line in lines if line.startswith("{")] + progress = [msg for msg in messages if msg["type"] == "archive_progress"] + # with --log-json, the progress of the archive being created consists of archive_progress objects ... + assert len(progress) >= 2 + assert not progress[0]["finished"] and progress[-1]["finished"] + assert {"nfiles", "original_size", "deduplicated_size", "path"} <= set(progress[0]) + # the final object has the final statistics: file2 was excluded. + assert progress[-1]["nfiles"] == 1 and progress[-1]["files_stats"] == {"A": 1, "d": 1} + # ... and not of text lines like "1.02 kB O 0 B U 1 N input/file1". + assert not any(re.search(r" O .* U \d+ N ", line) for line in lines if not line.startswith("{")) + + +def test_recreate_dry_run_progress(archivers, request, monkeypatch): + archiver = request.getfixturevalue(archivers) + monkeypatch.setenv("BORG_PROGRESS_FPS", "1000000") # no rate limit: the progress is reported after each item + cmd(archiver, "repo-create", RK_ENCRYPTION) + create_regular_file(archiver.input_path, "file1", size=1024 * 80) + create_regular_file(archiver.input_path, "file2", size=1024) + create_regular_file(archiver.input_path, "dir/file3", size=1024) + cmd(archiver, "create", "test", "input") + archives_before = cmd(archiver, "repo-list") + output = cmd(archiver, "recreate", "-a", "test", "--dry-run", "--log-json", "--progress", "-e", "input/file2") + messages = [json.loads(line) for line in output.splitlines() if line.startswith("{")] + progress = [msg for msg in messages if msg["type"] == "archive_progress"] + # a dry-run reports what would be in the new archive: file2 is excluded. it can not know what would be new. + assert len(progress) == 5 # input, input/dir, 2 files, the final object + counts = [msg["nfiles"] for msg in progress] + assert counts == sorted(counts) and counts[0] == 0 and counts[-1] == 2 + assert sorted(msg["path"] for msg in progress[:-1]) == ["input", "input/dir", "input/dir/file3", "input/file1"] + final = progress[-1] + assert final["finished"] and "path" not in final + assert final["original_size"] == 1024 * 81 and "deduplicated_size" not in final + # the text progress works also + output = cmd(archiver, "recreate", "-a", "test", "--dry-run", "--progress", "-e", "input/file2") + assert "82.94 kB O 0 B U 2 N input/" in output + assert cmd(archiver, "repo-list") == archives_before # nothing was changed + + +def test_recreate_files_stats(archivers, request, monkeypatch): + archiver = request.getfixturevalue(archivers) + monkeypatch.setenv("BORG_PROGRESS_FPS", "1000000") # no rate limit: the progress is reported after each item + cmd(archiver, "repo-create", RK_ENCRYPTION) + create_regular_file(archiver.input_path, "file1", size=1024) + create_regular_file(archiver.input_path, "file2", size=1024) + create_regular_file(archiver.input_path, "dir/file3", size=1024) + cmd(archiver, "create", "test", "input") + output = cmd(archiver, "recreate", "-a", "test", "--log-json", "--progress", "-e", "input/file2") + messages = [json.loads(line) for line in output.splitlines() if line.startswith("{")] + progress = [msg for msg in messages if msg["type"] == "archive_progress" and not msg["finished"]] + # the items of the new archive are counted by their status (as --list shows it), the excluded one is not. + assert progress[-1]["files_stats"] == {"A": 2, "d": 2} + assert progress[-1]["nfiles"] == 2 + + def test_comment(archivers, request): archiver = request.getfixturevalue(archivers) create_regular_file(archiver.input_path, "file1", size=1024 * 80) diff --git a/src/borg/testsuite/archiver/tar_cmds_test.py b/src/borg/testsuite/archiver/tar_cmds_test.py index ad0fd216ee..dead28d5d5 100644 --- a/src/borg/testsuite/archiver/tar_cmds_test.py +++ b/src/borg/testsuite/archiver/tar_cmds_test.py @@ -189,6 +189,39 @@ def test_import_tar_nfiles(archivers, request): assert info["archives"][0]["stats"]["nfiles"] == 3 +def test_import_tar_files_stats(archivers, request): + """import-tar counts the items by their status, like create does.""" + archiver = request.getfixturevalue(archivers) + with tarfile.open("input.tar", "w") as tar: + for name in ("dir/file1", "dir/file2"): + data = name.encode() + tarinfo = tarfile.TarInfo(name) + tarinfo.size = len(data) + tar.addfile(tarinfo, io.BytesIO(data)) + tarinfo = tarfile.TarInfo("dir/hardlink1") + tarinfo.type = tarfile.LNKTYPE + tarinfo.linkname = "dir/file1" + tar.addfile(tarinfo) + tarinfo = tarfile.TarInfo("dir/subdir") + tarinfo.type = tarfile.DIRTYPE + tar.addfile(tarinfo) + tarinfo = tarfile.TarInfo("dir/symlink1") + tarinfo.type = tarfile.SYMTYPE + tarinfo.linkname = "file1" + tar.addfile(tarinfo) + cmd(archiver, "repo-create", "--encryption=authenticated-sha256") + stats = json.loads(cmd(archiver, "import-tar", "--json", "dst", "input.tar"))["archive"]["stats"] + assert stats["files_stats"] == {"A": 2, "h": 1, "d": 1, "s": 1} + output = cmd(archiver, "import-tar", "--stats", "dst2", "input.tar") + assert "Added files: 2" in output + # the final archive_progress object has the final statistics + output = cmd(archiver, "import-tar", "--log-json", "--progress", "dst3", "input.tar") + messages = [json.loads(line) for line in output.splitlines() if line.startswith("{")] + final = [msg for msg in messages if msg["type"] == "archive_progress"][-1] + assert final["finished"] and final["nfiles"] == 3 + assert final["files_stats"] == {"A": 2, "h": 1, "d": 1, "s": 1} + + def test_import_tar_json(archivers, request): """import-tar --json reports the stats of the new archive like create --json does, see #10335.""" archiver = request.getfixturevalue(archivers) @@ -937,3 +970,23 @@ def set_acl(path, access=None, default=None): assert "acl_default" in extracted_dir_acl assert extracted_dir_acl["acl_default"] == dir_acl["acl_default"] assert b"user:root:r--" in dir_acl["acl_default"] + + +def test_export_tar_list_json(archivers, request): + archiver = request.getfixturevalue(archivers) + create_test_files(archiver.input_path) + os.unlink("input/flagfile") + cmd(archiver, "repo-create", RK_ENCRYPTION) + cmd(archiver, "create", "test", "input") + # the text listing has the "+" prefix, like the listing of borg extract + output = cmd(archiver, "export-tar", "test", "simple.tar", "--list", "--tar-format=GNU") + lines = output.splitlines() # the line ending depends on the platform + assert "+ input/file1" in lines + assert "+ input/dir2" in lines + # with --log-json, the listing consists of file_status objects (one per item), no text lines + output = cmd(archiver, "export-tar", "test", "simple2.tar", "--list", "--log-json", "--tar-format=GNU") + messages = [json.loads(line) for line in output.splitlines()] + file_status = [msg for msg in messages if msg["type"] == "file_status"] + assert {"type": "file_status", "status": "+", "path": "input/file1"} in file_status + assert {"type": "file_status", "status": "+", "path": "input/dir2"} in file_status + assert all(msg["status"] == "+" for msg in file_status) diff --git a/src/borg/testsuite/archiver/transfer_cmd_test.py b/src/borg/testsuite/archiver/transfer_cmd_test.py index 1e33aea6db..f512350fa1 100644 --- a/src/borg/testsuite/archiver/transfer_cmd_test.py +++ b/src/borg/testsuite/archiver/transfer_cmd_test.py @@ -447,6 +447,26 @@ def check_repo(): check_repo() +def test_transfer_progress_json(archivers, request, monkeypatch): + archiver = request.getfixturevalue(archivers) + with setup_repos(archiver, monkeypatch) as other_repo1: + create_test_files(archiver.input_path) + cmd(archiver, "create", "arch1", "input") + output = cmd(archiver, "transfer", other_repo1, "--log-json", "--progress") + lines = output.splitlines() + messages = [json.loads(line) for line in lines if line.startswith("{")] + progress = [msg for msg in messages if msg["type"] == "archive_progress"] + # with --log-json, the progress of the archive being created consists of archive_progress objects ... + assert len(progress) >= 2 + assert not progress[0]["finished"] and progress[-1]["finished"] + assert {"nfiles", "original_size", "deduplicated_size", "path"} <= set(progress[0]) + # the final object has the final statistics + listing = cmd(archiver, "list", "--format={type}{NL}", "arch1") + assert progress[-1]["nfiles"] == listing.splitlines().count("-") > 0 + # ... and not of text lines like "1.02 kB O 0 B U 1 N input/file1". + assert not any(re.search(r" O .* U \d+ N ", line) for line in lines if not line.startswith("{")) + + @pytest.mark.parametrize("rechunkify", [False, True]) def test_transfer_wrong_chunk_content(archivers, request, monkeypatch, rechunkify): # transferring re-anchors the content in another repository, so the chunkid == id_hash(content) diff --git a/src/borg/testsuite/archiver/undelete_cmd_test.py b/src/borg/testsuite/archiver/undelete_cmd_test.py index 431ed62b06..bcd39918fd 100644 --- a/src/borg/testsuite/archiver/undelete_cmd_test.py +++ b/src/borg/testsuite/archiver/undelete_cmd_test.py @@ -2,6 +2,8 @@ from ...constants import * # NOQA from ...helpers import CommandError +import json + from . import cmd, create_regular_file, generate_archiver_tests, RK_ENCRYPTION pytest_generate_tests = lambda metafunc: generate_archiver_tests(metafunc, kinds="local,binary") # NOQA @@ -125,3 +127,27 @@ def test_undelete_multiple_run(archivers, request): assert "normal" in output assert "deleted1" in output assert "deleted2" in output + + +def test_undelete_list_json(archivers, request): + archiver = request.getfixturevalue(archivers) + create_regular_file(archiver.input_path, "file1", size=1024 * 80) + cmd(archiver, "repo-create", RK_ENCRYPTION) + cmd(archiver, "create", "deleted1", "input") + cmd(archiver, "create", "deleted2", "input") + cmd(archiver, "delete", "deleted1") + cmd(archiver, "delete", "deleted2") + # with --log-json, the listing consists of archive_status objects (one per archive), no text lines + output = cmd(archiver, "undelete", "--dry-run", "--list", "--log-json", "-a", "sh:deleted*") + messages = [json.loads(line) for line in output.splitlines()] + statuses = [msg for msg in messages if msg["type"] == "archive_status"] + assert {(msg["name"], msg["status"]) for msg in statuses} == {("deleted1", "undeleted"), ("deleted2", "undeleted")} + for msg in statuses: + assert msg["message"].startswith("Would undelete: ") and msg["name"] in msg["message"] + assert msg["dry_run"] is True # the status is what would be done + assert msg["archive"] == msg["name"] and len(msg["id"]) == 64 and "T" in msg["time"] + output = cmd(archiver, "undelete", "--list", "--log-json", "-a", "sh:deleted1") + statuses = [msg for msg in map(json.loads, output.splitlines()) if msg["type"] == "archive_status"] + assert [(msg["name"], msg["status"], msg["dry_run"]) for msg in statuses] == [("deleted1", "undeleted", False)] + assert statuses[0]["message"].startswith("Undeleted archive: ") and statuses[0]["message"].endswith("(1/1)") + assert "deleted1" in cmd(archiver, "repo-list") diff --git a/src/borg/testsuite/cockpit_session_test.py b/src/borg/testsuite/cockpit_session_test.py new file mode 100644 index 0000000000..99036a2a41 --- /dev/null +++ b/src/borg/testsuite/cockpit_session_test.py @@ -0,0 +1,615 @@ +"""Tests for the cockpit's event parsing, session model and borg runner. They do not need Textual.""" + +import asyncio +import json +import sys +import time + +import pytest + +from borg.cockpit.events import ( + ArchiveProgress, + ArchiveStatus, + FileStatus, + LogMessage, + ProcessFinished, + ProgressMessage, + ProgressPercent, + Question, + RawLine, + UnknownJson, + parse_json_line, +) +from borg.archiver import Archiver +from borg.cockpit.runner import INJECTED_OPTIONS, BorgRunner, borg_command, unsupported_reason +from borg.cockpit.session import NO_TERMINAL_WARNING, NO_TERMINAL_HINT, Session + +# JSON lines as documented in docs/internals/frontends.rst +ARCHIVE_PROGRESS = ( + '{"original_size": 250012, "deduplicated_size": 250012, "nfiles": 3, "hashing_time": 0.5, "chunking_time": 0.25, ' + '"files_stats": {"A": 3, "d": 3}, "store_stats": {}, "path": "src/linux/file1", "time": 1787900398.684961, ' + '"type": "archive_progress", "finished": false}' +) +ARCHIVE_PROGRESS_FINISHED = ( + '{"original_size": 250999, "deduplicated_size": 250999, "nfiles": 4, "hashing_time": 0.5, "chunking_time": 0.25, ' + '"files_stats": {"A": 4, "d": 3}, "store_stats": {}, "time": 1787900398.686938, "type": "archive_progress", ' + '"finished": true}' +) +FILE_STATUS = '{"type": "file_status", "status": "A", "path": "src/linux/baz/file2"}' +PROGRESS_PERCENT = ( + '{"message": " 20.0% Extracting: src/linux/baz/file3", "current": 50012, "total": 250012, ' + '"info": ["src/linux/baz/file3"], "operation": 1, "msgid": "extract", "type": "progress_percent", ' + '"finished": false, "time": 1787900399.5558112}' +) +PROGRESS_PERCENT_FINISHED = ( + '{"message": "", "operation": 1, "msgid": "extract", "type": "progress_percent", "finished": true, ' + '"time": 1787900399.556339}' +) +PROGRESS_MESSAGE = ( + '{"message": "Saving files cache", "operation": 2, "msgid": "cache.close", "type": "progress_message", ' + '"finished": false, "time": 1787900398.719723}' +) +LOG_MESSAGE = ( + '{"type": "log_message", "time": 1787900383.5105972, "message": "Repository does not exist.", ' + '"levelname": "ERROR", "name": "borg.archiver", "msgid": "Repository.DoesNotExist"}' +) +QUESTION_PROMPT = ( + '{"type": "question_prompt", "msgid": "BORG_CHECK_I_KNOW_WHAT_I_AM_DOING", ' + '"message": "This is a potentially dangerous function.\\n' + "Type 'YES' if you understand this and want to continue: \"}" +) +QUESTION_ENV_ANSWER = ( + '{"env_var": "BORG_CHECK_I_KNOW_WHAT_I_AM_DOING", "type": "question_env_answer", ' + '"msgid": "BORG_CHECK_I_KNOW_WHAT_I_AM_DOING", "message": "NO (from BORG_CHECK_I_KNOW_WHAT_I_AM_DOING)"}' +) + + +def test_parse_log_message(): + event = parse_json_line(LOG_MESSAGE) + assert event == LogMessage( + message="Repository does not exist.", + levelname="ERROR", + name="borg.archiver", + msgid="Repository.DoesNotExist", + time=1787900383.5105972, + ) + + +def test_parse_progress_percent(): + event = parse_json_line(PROGRESS_PERCENT) + assert isinstance(event, ProgressPercent) + assert (event.operation, event.msgid, event.current, event.total) == (1, "extract", 50012, 250012) + assert event.info == ["src/linux/baz/file3"] + assert event.message.endswith("src/linux/baz/file3") + assert not event.finished + finished = parse_json_line(PROGRESS_PERCENT_FINISHED) + assert isinstance(finished, ProgressPercent) + assert finished.finished and finished.current is None and finished.total is None and finished.message == "" + + +def test_parse_progress_message(): + event = parse_json_line(PROGRESS_MESSAGE) + assert event == ProgressMessage( + operation=2, message="Saving files cache", msgid="cache.close", finished=False, time=1787900398.719723 + ) + + +def test_parse_archive_progress(): + event = parse_json_line(ARCHIVE_PROGRESS) + assert isinstance(event, ArchiveProgress) + assert (event.original_size, event.deduplicated_size, event.nfiles) == (250012, 250012, 3) + assert (event.hashing_time, event.chunking_time) == (0.5, 0.25) + assert event.files_stats == {"A": 3, "d": 3} + assert event.path == "src/linux/file1" + assert not event.finished + finished = parse_json_line(ARCHIVE_PROGRESS_FINISHED) + assert isinstance(finished, ArchiveProgress) + assert finished.finished and finished.path is None and finished.nfiles == 4 + + +def test_parse_file_status(): + assert parse_json_line(FILE_STATUS) == FileStatus(status="A", path="src/linux/baz/file2") + + +def test_parse_question(): + prompt = parse_json_line(QUESTION_PROMPT) + assert isinstance(prompt, Question) + assert prompt.kind == "prompt" and prompt.needs_answer + assert prompt.msgid == "BORG_CHECK_I_KNOW_WHAT_I_AM_DOING" + assert prompt.message.startswith("This is a potentially dangerous function.\n") + env_answer = parse_json_line(QUESTION_ENV_ANSWER) + assert isinstance(env_answer, Question) + assert env_answer.kind == "env_answer" and not env_answer.needs_answer + assert env_answer.env_var == "BORG_CHECK_I_KNOW_WHAT_I_AM_DOING" + + +def test_parse_unknown_type_and_missing_keys(): + assert parse_json_line('{"type": "something_new", "x": 1}') == UnknownJson({"type": "something_new", "x": 1}) + # no crash on missing / odd keys, defaults are used + assert parse_json_line('{"type": "log_message"}') == LogMessage(message="") + assert parse_json_line('{"type": "archive_progress", "files_stats": null, "nfiles": "3"}') == ArchiveProgress() + assert parse_json_line('{"type": "progress_percent", "operation": 7, "current": null}') == ProgressPercent( + operation=7, message="" + ) + + +@pytest.mark.parametrize("line", ["", "not json", "42", "[1, 2]", '"text"', '{"no": "type"}', '{"type": 5}']) +def test_parse_not_an_event(line): + assert parse_json_line(line) is None + + +def feed_lines(session, lines): + for line in lines: + event = parse_json_line(line) + session.feed(event if event is not None else RawLine(stream="stderr", line=line)) + + +def test_session_archive_progress(): + session = Session() + assert session.running and session.nfiles is None and session.original_size is None # unknown yet + assert session.files_stats == {} + feed_lines(session, [ARCHIVE_PROGRESS]) + assert session.nfiles == 3 + assert session.original_size == 250012 and session.deduplicated_size == 250012 + assert session.files_stats == {"A": 3, "d": 3} + assert session.count("A") == 3 and session.count("dbcs") == 3 and session.count("U") == 0 + assert session.progress_text == "src/linux/file1" + feed_lines(session, [ARCHIVE_PROGRESS_FINISHED]) + # the final object has the final statistics: what was processed after the previous (rate limited) object counts + assert session.archive_finished + assert session.nfiles == 4 and session.original_size == 250999 + assert session.files_stats == {"A": 4, "d": 3} + assert session.progress_text == "" + + +def test_session_counts_list_lines(): + session = Session() + session.feed(FileStatus(status="A", path="a")) + session.feed(FileStatus(status="A", path="b")) + session.feed(FileStatus(status="d", path="dir")) + session.feed(FileStatus(status="E", path="broken")) + assert session.status_counts == {"A": 2, "d": 1, "E": 1} + # the list lines are no source for the statistics of the archive: they are borg's statistics only. + assert session.nfiles is None and session.files_stats == {} and session.count("A") == 0 + lines, dropped = session.drain() + assert dropped == 0 + assert [(line.kind, line.tag, line.text) for line in lines] == [ + ("status", "A", "A a"), + ("status", "A", "A b"), + ("status", "d", "d dir"), + ("status", "E", "E broken"), + ] + session.feed(ArchiveProgress(nfiles=3, original_size=1000, deduplicated_size=10, files_stats={"A": 1, "d": 1})) + assert session.nfiles == 3 and session.files_stats == {"A": 1, "d": 1} + assert session.original_size == 1000 and session.deduplicated_size == 10 + + +def test_session_statistics_do_not_depend_on_the_listing(): + # create --list --filter=AME: only a few of the items are listed. + session = Session(command="create") + for number in range(3): + session.feed(FileStatus(status="M", path=f"modified{number}")) + session.feed(ArchiveProgress(nfiles=23223, original_size=5000, files_stats={"M": 3, "U": 23220, "d": 46})) + assert session.status_counts == {"M": 3} + assert session.nfiles == 23223 + assert session.count("U") == 23220 and session.count("M") == 3 and session.count("d") == 46 + session.sample(now=session.started + 1.0) + assert session.files_per_second == 23223.0 + + +def test_session_archive_status(): + session = Session() + session.feed(ArchiveStatus(name="a1", status="pruned", message="Would prune: a1", data={"kept": False})) + session.feed(ArchiveStatus(name="a2", status="kept", message="Keeping archive (rule: daily #1): a2")) + session.feed(ArchiveStatus(name="a3", status="kept", message="Keeping archive (rule: daily #2): a3")) + session.feed(ArchiveStatus(name="a4", status="deleted", message="Deleted archive: a4 (1/1)")) + assert session.archive_counts == {"kept": 2, "pruned": 1, "deleted": 1} + assert not session.archives_dry_run + assert session.files_stats == {} # archives are not items of a file listing + lines, _ = session.drain() + assert [(line.kind, line.tag, line.text) for line in lines] == [ + ("archive", "pruned", "Would prune: a1"), + ("archive", "kept", "Keeping archive (rule: daily #1): a2"), + ("archive", "kept", "Keeping archive (rule: daily #2): a3"), + ("archive", "deleted", "Deleted archive: a4 (1/1)"), + ] + # a dry-run: the status is what would be done + session.feed(ArchiveStatus(name="a5", status="pruned", message="Would prune: a5", dry_run=True)) + assert session.archives_dry_run and session.archive_counts["pruned"] == 2 + + +def test_session_phases(): + session = Session() + feed_lines(session, [PROGRESS_PERCENT, PROGRESS_MESSAGE]) + assert list(session.phases) == [1, 2] + extract = session.phases[1] + assert (extract.msgid, extract.current, extract.total, extract.finished) == ("extract", 50012, 250012, False) + assert extract.fraction == pytest.approx(0.2, abs=0.001) + assert session.phases[2].fraction is None + assert session.progress_text == "Saving files cache" + feed_lines(session, [PROGRESS_PERCENT_FINISHED]) + assert extract.finished and extract.message.endswith("file3") # the message of the last update stays + assert session.progress_text == "" + # extract first reports a total of 0 while it computes the total, that must not crash the fraction + session.feed(ProgressPercent(operation=3, message="Calculating total archive size...", current=0, total=0)) + assert session.phases[3].fraction is None + + +def test_session_questions(): + session = Session() + feed_lines(session, [QUESTION_PROMPT]) + assert session.pending_question is not None and session.pending_question.needs_answer + lines, _ = session.drain() + assert lines[0].kind == "log" and lines[0].tag == "PROMPT" + feed_lines(session, [QUESTION_ENV_ANSWER]) + assert session.pending_question is None + + +def test_session_drain_is_bounded(): + session = Session() + n = 2 * Session.LINES_MAX + 5 + for i in range(n): + session.feed(RawLine(stream="stdout", line=f"line {i}")) + lines, dropped = session.drain() + assert len(lines) == Session.LINES_MAX + assert dropped == n - Session.LINES_MAX + assert lines[0].text == f"line {n - Session.LINES_MAX}" and lines[-1].text == f"line {n - 1}" + assert lines[0].kind == "raw" and lines[0].tag == "stdout" + assert session.drain() == ([], 0) + + +def test_session_sample_rates(): + session = Session() + session.feed(ArchiveProgress(nfiles=10, original_size=1000, deduplicated_size=100)) + session.sample(now=session.started + 2.0) + assert session.files_per_second == 5.0 + assert session.original_bytes_per_second == 500.0 + assert session.deduplicated_bytes_per_second == 50.0 + session.feed(ArchiveProgress(nfiles=10, original_size=1000, deduplicated_size=100)) + session.sample(now=session.started + 3.0) + assert session.files_per_second == 0.0 + session.sample(now=session.started + 3.0) # no time passed: keep the rates + assert session.files_per_second == 0.0 + + +def test_session_passphrase_hint(): + session = Session() + session.feed(RawLine(stream="stderr", line=NO_TERMINAL_WARNING)) + session.feed(RawLine(stream="stderr", line="Enter passphrase for key /repo: ", partial=True)) + assert session.passphrase_needed + lines, _ = session.drain() + assert [(line.kind, line.text) for line in lines] == [ + ("raw", NO_TERMINAL_WARNING), + ("hint", NO_TERMINAL_HINT), + ("raw", "Enter passphrase for key /repo: "), + ] + + +def test_session_process_finished(): + session = Session() + feed_lines(session, [QUESTION_PROMPT, PROGRESS_MESSAGE]) + session.feed(ProcessFinished(rc=2, error="boom")) + assert not session.running and session.rc == 2 and session.error == "boom" + assert session.pending_question is None and session.progress_text == "" + elapsed = session.elapsed + time.sleep(0.01) + assert session.elapsed == elapsed # frozen + lines, _ = session.drain() + assert lines[-1].kind == "log" and lines[-1].tag == "ERROR" and lines[-1].text == "boom" + + +def test_borg_command(): + assert borg_command(["create", "arch", "src"], executable=["borg"]) == [ + "borg", + "--log-json", + "--progress", + "create", + "arch", + "src", + ] + # no duplicates when the user gave them already + assert borg_command(["--progress", "create"], executable=["borg"]) == ["borg", "--log-json", "--progress", "create"] + assert borg_command(["create", "--log-json"], executable=["borg"]) == ["borg", "--progress", "create", "--log-json"] + # the default runs the interpreter that runs the cockpit + assert borg_command(["--version"])[: -len(INJECTED_OPTIONS) - 1] == [sys.executable, "-m", "borg"] + + +FAKE_BORG = """ +import json, sys + +def err(obj): + sys.stderr.write(json.dumps(obj) + "\\n") + sys.stderr.flush() + +err({"type": "log_message", "levelname": "INFO", "name": "borg.test", "message": "hello"}) +err({"type": "file_status", "status": "A", "path": "a/b"}) +sys.stderr.write("plain text\\n") +sys.stderr.flush() +print("stdout line", flush=True) +sys.stderr.write("Enter something: ") # a prompt: no newline, waits for stdin +sys.stderr.flush() +answer = sys.stdin.readline().strip() +print("got " + answer, flush=True) +sys.exit(2) +""" + + +def test_runner(): + events = [] + runner = BorgRunner(["--whatever"], events.append, executable=[sys.executable, "-c", FAKE_BORG]) + runner.PARTIAL_LINE_TIMEOUT = 0.2 + + async def run(): + task = asyncio.create_task(runner.start()) + deadline = time.monotonic() + 30 + while not any(isinstance(e, RawLine) and e.partial for e in events): + assert time.monotonic() < deadline, f"no partial line seen, events: {events}" + await asyncio.sleep(0.02) + await runner.answer("YES") + await asyncio.wait_for(task, 30) + + asyncio.run(run()) + assert LogMessage(message="hello", levelname="INFO", name="borg.test") in events + assert FileStatus(status="A", path="a/b") in events + assert RawLine(stream="stderr", line="plain text") in events + assert RawLine(stream="stdout", line="stdout line") in events + assert RawLine(stream="stderr", line="Enter something: ", partial=True) in events + assert RawLine(stream="stdout", line="got YES") in events + assert events[-1] == ProcessFinished(rc=2) + assert runner.process is None + + +FAKE_BORG_BULK_DATA = """ +import sys + +out = sys.stdout.buffer +out.write(b"first line\\n") +for i in range(64): + out.write(b"\\0" * (1024 * 1024)) # 64 MiB without a line end +out.write(b"\\nlast line\\n") +""" + + +def test_runner_bounds_overlong_lines(): + events = [] + runner = BorgRunner([], events.append, executable=[sys.executable, "-c", FAKE_BORG_BULK_DATA]) + started = time.monotonic() + asyncio.run(asyncio.wait_for(runner.start(), 120)) + assert time.monotonic() - started < 60 # unbounded, the buffer handling was quadratic (minutes for this) + start_of_data = "\0" * runner.LINE_MAX_SHOWN + " [...]" + assert events == [ + RawLine(stream="stdout", line="first line"), + RawLine(stream="stdout", line=start_of_data, partial=True), # the rest of the data was dropped + RawLine(stream="stdout", line="last line"), + ProcessFinished(rc=0), + ] + + +def test_runner_disables_cockpit_for_borg(monkeypatch): + # the cockpit can be enabled via the environment (or the config file), that must not apply to the borg it runs. + monkeypatch.setenv("BORG_COCKPIT", "true") + assert Archiver().parse_args(["-r", "/some/repo", "check"]).cockpit + events = [] + fake_borg = "import os; print(os.environ.get('BORG_COCKPIT'))" + runner = BorgRunner([], events.append, executable=[sys.executable, "-c", fake_borg]) + asyncio.run(asyncio.wait_for(runner.start(), 30)) + assert events == [RawLine(stream="stdout", line="false"), ProcessFinished(rc=0)] + monkeypatch.setenv("BORG_COCKPIT", "false") # what the runner sets is a value borg accepts + assert not Archiver().parse_args(["-r", "/some/repo", "check"]).cockpit + + +def test_runner_start_failure(): + events = [] + runner = BorgRunner([], events.append, executable=["/nonexistent/borg-binary"]) + asyncio.run(runner.start()) + assert len(events) == 1 + assert isinstance(events[0], ProcessFinished) and events[0].rc == -1 and events[0].error + + +def test_borg_command_json_stdout(): + assert borg_command(["create", "x"], executable=["borg"], json_stdout=True) == [ + "borg", + "--log-json", + "--progress", + "create", + "x", + "--json", + ] + # --json goes before a "--" end-of-options marker, and is not duplicated + assert borg_command(["create", "x", "--", "-p"], executable=["borg"], json_stdout=True)[-4:] == [ + "x", + "--json", + "--", + "-p", + ] + assert borg_command(["create", "--json", "x"], executable=["borg"], json_stdout=True).count("--json") == 1 + + +FINAL_JSON = """ +{ + "archive": { + "duration": 90.5, + "id": "0123abcd0123abcd", + "name": "test", + "stats": { + "chunking_time": 0.25, + "deduplicated_size": 300, + "files_stats": {"A": 2, "M": 1, "d": 1}, + "hashing_time": 0.5, + "nfiles": 3, + "original_size": 3000, + "store_stats": {"store_calls": 7, "store_volume": 2048} + } + }, + "repository": {"id": "abcd", "location": "/repo"} +} +""" + + +def test_session_final_stats_from_stdout(): + session = Session(command="create", capture_stdout=True) + session.feed(ArchiveProgress(nfiles=2, original_size=2000, deduplicated_size=200, files_stats={"A": 2})) + session.feed(FileStatus(status="A", path="a")) + for line in FINAL_JSON.splitlines(): + session.feed(RawLine(stream="stdout", line=line)) + assert session.final_json is None and session.stdout_lines # only parsed at the end + lines, _ = session.drain() + assert [line.kind for line in lines] == ["status"] # the captured stdout is not logged + session.feed(ProcessFinished(rc=0)) + assert session.final_json["archive"]["name"] == "test" + assert session.archive_name == "test" and session.archive_duration == 90.5 + # the final statistics win over archive_progress + assert session.nfiles == 3 and session.files_stats == {"A": 2, "M": 1, "d": 1} + assert session.original_size == 3000 and session.deduplicated_size == 300 + lines, _ = session.drain() + assert all(line.kind == "log" and line.tag == "STATS" for line in lines) + assert [line.text for line in lines] == [ + "Archive name: test", + "Archive fingerprint: 0123abcd0123abcd", + "Duration: 1 minutes 30.500 seconds", + "Number of files: 3", + "Original size: 3.00 kB", + "Deduplicated size: 300 B", + "Time spent in hashing: 0.500 seconds", + "Time spent in chunking: 0.250 seconds", + "Added files: 2", + "Unchanged files: 0", + "Modified files: 1", + "Error files: 0", + "Files changed while reading: 0", + "Store store calls: 7", + "Store store volume: 2.05 kB", + ] + + +def test_session_final_stats_dry_run(): + session = Session(command="create", capture_stdout=True) + # a dry-run has no archive_progress, the statistics are unknown until the end, whatever gets listed. + session.feed(FileStatus(status="+", path="included")) + session.feed(FileStatus(status="-", path="excluded")) + assert session.nfiles is None and session.original_size is None and session.files_stats == {} + session.sample(now=session.started + 1.0) + assert session.files_per_second == 0.0 + session.drain() + for line in '{"dry_run": true, "stats": {"nfiles": 5, "original_size": 1234}, "repository": {}}'.splitlines(): + session.feed(RawLine(stream="stdout", line=line)) + session.feed(ProcessFinished(rc=0)) + assert session.archive_name is None + assert session.nfiles == 5 and session.original_size == 1234 and session.deduplicated_size is None + assert session.files_stats == {} # borg does not tell them for a dry-run + lines, _ = session.drain() + assert [line.text for line in lines] == [ + "Dry run: no archive was created.", + "Number of files: 5", + "Original size: 1.23 kB", + ] + + +def test_session_stdout_that_is_not_json(): + session = Session(command="create", capture_stdout=True) + session.feed(RawLine(stream="stdout", line="just text")) + session.feed(ProcessFinished(rc=2)) + assert session.final_json is None and session.final_stats is None + lines, _ = session.drain() + assert [(line.kind, line.text) for line in lines] == [("raw", "just text")] + + +def test_session_counts_warnings(): + session = Session() + session.feed(LogMessage(message="w", levelname="WARNING")) + session.feed(LogMessage(message="e", levelname="ERROR")) + session.feed(LogMessage(message="c", levelname="CRITICAL")) + session.feed(LogMessage(message="i", levelname="INFO")) + assert (session.warnings, session.errors) == (1, 2) + + +def test_session_phase_lookup_and_rates(): + session = Session() + session.feed(ProgressPercent(operation=1, msgid="extract", message="", current=0, total=1000)) + session.feed(ProgressMessage(operation=2, msgid="cache.close", message="Saving")) + assert session.phase("extract").operation == 1 and session.phase("nope") is None + assert session.active_phase.operation == 2 + session.sample(now=session.started + 1.0) + session.feed(ProgressPercent(operation=1, msgid="extract", message="", current=500, total=1000)) + session.sample(now=session.started + 2.0) + assert session.phase("extract").rate == 500.0 + assert session.active_phase.operation == 1 + session.feed(ProgressPercent(operation=1, msgid="extract", finished=True, message="")) + assert session.active_phase is None + session.sample(now=session.started + 3.0) + assert session.phase("extract").rate == 0.0 + # after the run, the rates are zero + session.feed(ArchiveProgress(nfiles=100)) + session.feed(ProcessFinished(rc=0)) + session.sample(now=session.started + 4.0) + assert session.files_per_second == 0.0 + + +def test_parse_archive_status(): + line = ( + '{"name": "daily-2026-09-09", "archive": "daily-2026-09-09", "id": "ab12", ' + '"time": "2026-09-09T02:00:00+02:00", ' + '"group": {"name": "daily"}, "kept": true, "keep_rule": "daily", "kept_oldest": false, ' + '"kept_archive_number": 1, "status": "kept", "dry_run": true, "type": "archive_status", ' + '"message": "Keeping archive (rule: daily #1): ..."}' + ) + event = parse_json_line(line) + assert isinstance(event, ArchiveStatus) + assert (event.name, event.status, event.dry_run) == ("daily-2026-09-09", "kept", True) + assert event.message.startswith("Keeping archive") + assert event.data["keep_rule"] == "daily" and event.data["group"] == {"name": "daily"} + line = '{"type": "archive_status", "name": "old", "status": "deleted", "message": "Deleted archive: old (1/1)"}' + assert parse_json_line(line) == ArchiveStatus( + name="old", status="deleted", message="Deleted archive: old (1/1)", data=json.loads(line) + ) + + +class FakeStream: + def __init__(self, is_terminal): + self.is_terminal = is_terminal + + def isatty(self): + return self.is_terminal + + +@pytest.mark.parametrize( + "argv, reason", + [ + (["create", "archive", "-"], "stdin"), + (["create", "archive", "input", "-"], "stdin"), + (["create", "--paths-from-stdin", "archive"], "stdin"), + (["import-tar", "archive", "-"], "stdin"), + (["key", "import", "-"], "stdin"), + (["key", "import", "--paper"], "stdin"), + (["serve"], "stdin"), + (["extract", "--stdout", "archive"], "stdout"), + (["export-tar", "archive", "-"], "stdout"), + (["extract", "archive"], None), + (["export-tar", "archive", "file.tar"], None), + (["create", "archive", "input"], None), + (["create", "--paths-from-command", "archive", "--", "find", "."], None), + (["import-tar", "archive", "file.tar"], None), + (["key", "import", "keyfile"], None), + (["check", "--repair"], None), + ], +) +def test_unsupported_reason(argv, reason): + # the real parser gives the args, so this also checks the names of the options. + args = Archiver().parse_args(["-r", "/some/repo"] + argv) + result = unsupported_reason(args, streams=(FakeStream(True),) * 3) + if reason is None: + assert result is None + else: + assert reason in result + + +@pytest.mark.parametrize("redirected", [0, 1, 2]) +def test_unsupported_reason_no_terminal(redirected): + args = Archiver().parse_args(["-r", "/some/repo", "check"]) + streams = [FakeStream(True), FakeStream(True), FakeStream(True)] + streams[redirected] = FakeStream(False) + assert "needs a terminal" in unsupported_reason(args, streams=streams) + streams[redirected] = None # e.g. a closed stdin + assert "needs a terminal" in unsupported_reason(args, streams=streams) + # pytest captures the output, so the default streams are not terminals either. + assert "needs a terminal" in unsupported_reason(args) diff --git a/src/borg/testsuite/cockpit_test.py b/src/borg/testsuite/cockpit_test.py index be1a30d7a5..48fb816281 100644 --- a/src/borg/testsuite/cockpit_test.py +++ b/src/borg/testsuite/cockpit_test.py @@ -1,12 +1,32 @@ +"""Tests for the cockpit application. They need Textual; the borg process is faked, except in the slow test.""" + import asyncio +import json +import os +import signal import subprocess +import time import pytest +from borg.cockpit.events import ( + ArchiveProgress, + ArchiveStatus, + FileStatus, + LogMessage, + ProcessFinished, + ProgressMessage, + ProgressPercent, + Question, + RawLine, +) from borg.platformflags import is_freebsd, is_win32 try: from borg.cockpit.app import BorgCockpitApp + from borg.cockpit.prompt import ConfirmQuitModal, PromptModal + from borg.cockpit.screens import CreateScreen, ExtractScreen, GenericScreen, screen_for_command + from borg.cockpit.widgets import printable have_cockpit = True except ImportError: @@ -15,6 +35,430 @@ pytestmark = pytest.mark.skipif(not have_cockpit, reason="can not import BorgCockpitApp, is textual installed?") +class FakeRunner: + """Replays events instead of running borg. After a prompt, it waits for the answer.""" + + def __init__(self, args, callback, events=(), rc=0, json_stdout=False): + self.args = list(args) + self.callback = callback + self.events = list(events) + self.rc = rc + self.json_stdout = json_stdout + self.answers = [] + self.answered = asyncio.Event() + + async def start(self): + for event in self.events: + self.callback(event) + if isinstance(event, Question) and event.needs_answer: + await self.answered.wait() + self.answered.clear() + await asyncio.sleep(0) + self.callback(ProcessFinished(rc=self.rc)) + + async def answer(self, text): + self.answers.append(text) + self.answered.set() + + async def stop(self): + pass + + +def make_runner_factory(events, rc=0): + """A runner_factory for BorgCockpitApp, remembering the FakeRunner it created in the returned list.""" + created = [] + + def factory(args, callback, **kwargs): + runner = FakeRunner(args, callback, events=events, rc=rc, **kwargs) + created.append(runner) + return runner + + return factory, created + + +async def wait_until(pilot, predicate, timeout=10.0): + deadline = time.monotonic() + timeout + while not predicate(): + assert time.monotonic() < deadline, "timeout while waiting for the app" + await pilot.pause(0.05) + + +async def run_to_the_end(app, inspect=None): + """ + Run the app until the (fake) borg has finished and the widgets show the final state. + + Returns the texts shown by the status panel, the log text and the result of inspect(app), if given + (the widgets can only be inspected while the app runs). + """ + async with app.run_test(size=(100, 30)) as pilot: + await wait_until(pilot, lambda: not app.session.running) + await pilot.pause(0.5) # let the refresh timer show the final state + check_layout(app) + return app.query_one("#status").shown, log_text(app), inspect(app) if inspect else None + + +def log_text(app): + return "\n".join(strip.text for strip in app.query_one("#standard-log-content").lines) + + +def check_layout(app): + """The status panel must fit into the top row, next to the logo, with the log panel below.""" + top_row, status, log = app.query_one("#top-row"), app.query_one("#status"), app.query_one("#standard-log") + assert top_row.size.height == status.HEIGHT # size is the content area, without the border + assert status.region.bottom <= top_row.region.bottom + rc_line = app.query_one("#status-rc") + assert rc_line.region.height == 1 and rc_line.region.bottom <= status.region.bottom + assert log.region.y >= top_row.region.bottom and log.size.height >= 5 + + +FINAL_JSON = { + "archive": { + "name": "test", + "id": "0123abcd" * 8, + "duration": 1.5, + "stats": { + "nfiles": 3, + "original_size": 3000, + "deduplicated_size": 300, + "hashing_time": 0.1, + "chunking_time": 0.2, + "files_stats": {"A": 2, "M": 1, "d": 1}, + "store_stats": {"store_calls": 7}, + }, + }, + "repository": {"id": "ab" * 32, "location": "/repo"}, +} + + +def test_screen_for_command(): + assert screen_for_command("create") is CreateScreen + assert screen_for_command("import-tar") is CreateScreen + assert screen_for_command("extract") is ExtractScreen + assert screen_for_command("export-tar") is ExtractScreen + assert screen_for_command("check") is GenericScreen + assert screen_for_command(None) is GenericScreen + + +def test_app_create_screen(): + events = [ + LogMessage(message="Creating archive", levelname="INFO"), + LogMessage(message="something is odd", levelname="WARNING"), + ArchiveProgress( + original_size=1000, deduplicated_size=100, nfiles=2, files_stats={"A": 1, "M": 1}, path="src/a" + ), + FileStatus(status="A", path="src/a"), + FileStatus(status="M", path="src/b"), + FileStatus(status="d", path="src"), + ArchiveProgress( + original_size=2900, deduplicated_size=290, nfiles=3, files_stats={"A": 2, "M": 1, "d": 1}, path="src/c" + ), + ArchiveProgress( + original_size=2950, deduplicated_size=295, nfiles=3, files_stats={"A": 2, "M": 1, "d": 1}, finished=True + ), + ] + events += [RawLine(stream="stdout", line=line) for line in json.dumps(FINAL_JSON, indent=4).splitlines()] + factory, runners = make_runner_factory(events, rc=1) + app = BorgCockpitApp(borg_args=["create", "test", "src"], command="create", runner_factory=factory) + shown, text, _ = asyncio.run(run_to_the_end(app)) + assert isinstance(app.main_screen, CreateScreen) + assert runners[0].args == ["create", "test", "src"] and runners[0].json_stdout + # the final numbers come from the --json output + assert shown["status-files"] == "Files: 3" + assert shown["status-original"] == "Original: 3.00 kB" + assert shown["status-deduplicated"] == "Deduplicated: 300 B (10.0%)" + assert shown["status-added"] == "Added: 2" and shown["status-modified"] == "Modified: 1" + assert shown["status-unchanged"] == "Unchanged: 0" + assert shown["status-other"] == "Other: 1" and shown["status-errors"] == "Errors: 0" + assert shown["status-warnings"] == "Warnings: 1" + assert shown["status-activity"].startswith("Archive: test (1.") + assert shown["status-rc"] == "RC: 1" + assert "Creating archive" in text and "something is odd" in text + assert "A src/a" in text and "M src/b" in text and "d src" in text + assert "Archive name: test" in text and "Number of files: 3" in text and "Store store calls: 7" in text + + +def test_app_create_screen_shows_the_statistics_of_borg(): + # the --list lines (here: reduced by --filter) must not influence the numbers, see also the session tests. + events = [FileStatus(status="M", path=f"src/modified{number}") for number in range(3)] + events.append( + ArchiveProgress(original_size=5000, deduplicated_size=50, nfiles=100, files_stats={"M": 3, "U": 97, "d": 5}) + ) + factory, runners = make_runner_factory(events) + app = BorgCockpitApp(borg_args=["recreate"], command="recreate", runner_factory=factory) # no final --json + shown, text, _ = asyncio.run(run_to_the_end(app)) + assert shown["status-files"] == "Files: 100" + assert shown["status-unchanged"] == "Unchanged: 97" and shown["status-modified"] == "Modified: 3" + assert shown["status-added"] == "Added: 0" and shown["status-other"] == "Other: 5" + assert shown["status-errors"] == "Errors: 0" + assert "M src/modified2" in text + + +def test_app_create_screen_shows_unknown_statistics_as_unknown(): + # a dry-run: borg only tells the number of files and the original size, and only at the end. + events = [FileStatus(status="+", path="src/a"), FileStatus(status="-", path="src/b")] + final_json = {"dry_run": True, "stats": {"nfiles": 1, "original_size": 1000}, "repository": {}} + events += [RawLine(stream="stdout", line=line) for line in json.dumps(final_json, indent=4).splitlines()] + factory, runners = make_runner_factory(events) + app = BorgCockpitApp(borg_args=["create", "--dry-run"], command="create", runner_factory=factory) + shown, text, _ = asyncio.run(run_to_the_end(app)) + assert shown["status-files"] == "Files: 1" and shown["status-original"] == "Original: 1.00 kB" + assert shown["status-deduplicated"] == "Deduplicated: -" + assert shown["status-unchanged"] == "Unchanged: -" and shown["status-modified"] == "Modified: -" + assert shown["status-added"] == "Added: -" and shown["status-other"] == "Other: -" + assert shown["status-errors"] == "Errors: -" + assert "+ src/a" in text and "- src/b" in text + + +def test_app_extract_screen(): + events = [ + ProgressPercent(operation=1, msgid="extract", message="Calculating total archive size", current=0, total=0), + ProgressPercent(operation=1, msgid="extract", message=" 25.0% Extracting: a", current=250, total=1000), + FileStatus(status="+", path="a"), + FileStatus(status="-", path="b"), + ProgressPercent(operation=1, msgid="extract", message=" 75.0% Extracting: c", current=750, total=1000), + ProgressPercent(operation=1, msgid="extract", finished=True, message=""), + ProgressPercent(operation=2, msgid="extract.permissions", message="Setting directory permissions 50%"), + ] + factory, runners = make_runner_factory(events) + app = BorgCockpitApp(borg_args=["extract", "--list", "test"], command="extract", runner_factory=factory) + shown, text, bar = asyncio.run( + run_to_the_end(app, lambda app: (app.query_one("#extract-bar").total, app.query_one("#extract-bar").progress)) + ) + assert isinstance(app.main_screen, ExtractScreen) + assert not runners[0].json_stdout + assert bar == (1000, 1000) # finished: complete + assert shown["status-extracted"] == "Extracted: 1.00 kB / 1.00 kB" + assert shown["status-items"] == "Items: 2" + assert shown["status-included"] == "Included: 1" and shown["status-excluded"] == "Excluded: 1" + assert shown["status-rc"] == "RC: 0" + assert "+ a" in text and "- b" in text + + +def test_app_generic_screen(): + events = [ + ProgressPercent(operation=1, msgid="check.index", message="Checking index 50%", current=50, total=100), + ProgressMessage(operation=2, msgid="cache.close", message="Saving files cache"), + ProgressPercent(operation=1, msgid="check.index", finished=True, message=""), + LogMessage(message="Archive consistency check complete, no problems found.", levelname="INFO"), + ArchiveStatus(name="old", status="pruned", message="Would prune: old", dry_run=True), + ArchiveStatus(name="new", status="kept", message="Keeping archive (rule: daily #1): new", dry_run=True), + ] + factory, runners = make_runner_factory(events) + app = BorgCockpitApp(borg_args=["check"], command="check", runner_factory=factory) + shown, text, _ = asyncio.run(run_to_the_end(app)) + assert isinstance(app.main_screen, GenericScreen) + assert shown["phases-title"] == "Phases" + assert shown["phases"].plain.splitlines() == [ + "✔ ██████████ Checking index", # finished: without the last percentage + "▶ ░░░░░░░░░░ Saving files cache", + ] + assert [str(span.style) for span in shown["phases"].spans] == ["green", "bold white"] + assert shown["status-warnings"] == "Warnings: 0" and shown["status-rc"] == "RC: 0" + assert shown["status-archives"] == "Archives: 1 kept, 1 pruned (dry-run)" + assert "no problems found" in text and "Would prune: old" in text + + +# Texts that mean something to a markup parser. They can be part of a path, an archive name or a message, +# and the cockpit must show them as they are (a MarkupError would end the app and thus the borg run). +MARKUP_LIKE_TEXTS = [ + "a[/b", + "[/", + "[red]x[/red]", + "[bold", + "back\\slash\\", + "a\\[b", + "[@click=app.quit]x[/]", + "$x [link=y]z[/]", +] + + +def test_app_shows_text_from_borg_as_it_is(): + events = [] + for number, text in enumerate(MARKUP_LIKE_TEXTS): + events += [ + FileStatus(status="A", path=text), + LogMessage(message=f"log {text}", levelname="WARNING"), + ArchiveStatus(name=text, status="kept", message=f"Keeping {text}"), + ProgressMessage(operation=number, msgid="test", message=f"phase {text}"), + ] + factory, runners = make_runner_factory(events) + app = BorgCockpitApp(borg_args=["prune"], command="prune", runner_factory=factory) + + def rendered(app): + panel = app.query_one("#status") + lines = [] + for text in MARKUP_LIKE_TEXTS: # a line of the panel, like the one showing the current path + panel.show_value("status-archives", "Archives: ", text, truncate=True) + lines.append(panel.query_one("#status-archives").render_line(0).text.rstrip()) + phases = [panel.query_one("#phases").render_line(y).text.rstrip() for y in range(len(MARKUP_LIKE_TEXTS))] + return lines, phases + + shown, text, (lines, phases) = asyncio.run(run_to_the_end(app, inspect=rendered)) + assert lines == [f"Archives: {text}" for text in MARKUP_LIKE_TEXTS] + assert phases == [f"▶ ░░░░░░░░░░ phase {text}" for text in MARKUP_LIKE_TEXTS] + log_lines = [line.rstrip() for line in text.splitlines()] + for text in MARKUP_LIKE_TEXTS: + assert f"A {text}" in log_lines + assert f"log {text}" in log_lines + assert f"Keeping {text}" in log_lines + + +def test_printable(): + assert printable("plain text, ünïcödé \u20ac") == "plain text, ünïcödé \u20ac" + assert ( + printable("esc\x1b[2J nul\x00 cr\r bel\x07 del\x7f csi\x9b2J") + == "esc\ufffd[2J nul\ufffd cr\ufffd bel\ufffd del\ufffd csi\ufffd2J" + ) + assert printable("line1\nline2\tx") == "line1\ufffdline2\ufffdx" + assert printable("line1\nline2\tx\x1b", multiline=True) == "line1\nline2\tx\ufffd" + + +def test_app_does_not_show_control_characters(): + # e.g. a file name can contain an ESC, starting an escape sequence the terminal would interpret. + evil, shown_as = "evil\x1b[2J\x1b]0;title\x07\x00\rname", "evil\ufffd[2J\ufffd]0;title\ufffd\ufffd\ufffdname" + events = [ + FileStatus(status="A", path=evil), + LogMessage(message=f"log {evil}", levelname="WARNING"), + ArchiveStatus(name=evil, status="kept", message=f"Keeping {evil}"), + ProgressMessage(operation=1, msgid="test", message=f"phase {evil}"), + RawLine(stream="stderr", line=f"raw {evil}"), + ] + factory, runners = make_runner_factory(events) + app = BorgCockpitApp(borg_args=["prune"], command="prune", runner_factory=factory) + + def rendered(app): + panel = app.query_one("#status") + panel.show_value("status-archives", "Archives: ", evil + "\nline2", truncate=True) + value = panel.query_one("#status-archives").render_line(0).text.rstrip() + return value, panel.query_one("#phases").render_line(0).text.rstrip() + + shown, text, (value, phase) = asyncio.run(run_to_the_end(app, inspect=rendered)) + assert value == f"Archives: {shown_as}\ufffdline2" # a panel line stays one line + assert phase == f"▶ ░░░░░░░░░░ phase {shown_as}" + log_lines = [line.rstrip() for line in text.splitlines()] + for line in f"A {shown_as}", f"log {shown_as}", f"Keeping {shown_as}", f"raw {shown_as}": + assert line in log_lines + assert not any(ord(char) < 0x20 or 0x7F <= ord(char) < 0xA0 for line in log_lines for char in line) + assert PromptModal(f"Really delete {evil}?\nType YES:").message == f"Really delete {shown_as}?\nType YES:" + + +def test_app_answers_prompt(): + events = [ + Question(kind="prompt", message="Do something dangerous? [yN]: ", msgid="BORG_TEST_PROMPT"), + Question(kind="accepted_true", message="Doing it."), + ] + factory, runners = make_runner_factory(events) + + async def run(): + app = BorgCockpitApp(borg_args=["check", "--repair"], command="check", runner_factory=factory) + async with app.run_test() as pilot: + await wait_until(pilot, lambda: isinstance(app.screen, PromptModal)) + assert app.session.pending_question is not None + + # the dialog must be composed and laid out before it can be clicked + def dialog_ready(): + buttons = app.screen.query("#prompt-yes") + return bool(buttons) and buttons.first().region.width > 0 + + await wait_until(pilot, dialog_ready) + await pilot.pause(0.1) + await pilot.click("#prompt-yes") + await wait_until(pilot, lambda: not app.session.running) + assert runners[0].answers == ["YES"] + assert app.session.pending_question is None + await pilot.pause(0.5) + assert app.query_one("#status").shown["status-rc"] == "RC: 0" + assert "Doing it." in log_text(app) + + asyncio.run(run()) + + +class EndlessRunner: + """A fake borg that runs until it gets terminated.""" + + def __init__(self, args, callback, json_stdout=False): + self.callback = callback + self.stopped = asyncio.Event() + + async def start(self): + await self.stopped.wait() + self.callback(ProcessFinished(rc=143)) # what borg exits with after a SIGTERM + + async def answer(self, text): + pass + + async def stop(self): + self.stopped.set() + + +@pytest.mark.skipif(is_win32, reason="the event loop does not support signal handlers on Windows") +@pytest.mark.parametrize("name", ["SIGTERM", "SIGHUP", "SIGINT"]) +def test_app_ends_orderly_on_signal(name): + async def run(): + app = BorgCockpitApp(borg_args=["create"], command="create", runner_factory=EndlessRunner) + async with app.run_test() as pilot: + # only send the signal if the app handles it, it would end the test process otherwise. + await wait_until(pilot, lambda: name in app.handled_signals) + assert app.session.running + os.kill(os.getpid(), getattr(signal, name)) + await wait_until(pilot, lambda: not app.is_running) + return app + + app = asyncio.run(run()) + assert app.runner.stopped.is_set() # borg was terminated ... + assert app.session.rc == 143 # ... and waited for, main() exits with this exit code + + +def press(app, key): + """ + Press a key. pilot.press() can not be used with this app: it waits until no animation runs anymore, + but the pulsar and the slogan of the logo panel keep changing their color all the time. + """ + app.simulate_key(key) + + +def test_app_quit_needs_confirmation_while_borg_runs(monkeypatch): + monkeypatch.setattr(BorgCockpitApp, "QUIT_DELAY", 0) + + async def run(): + app = BorgCockpitApp(borg_args=["create"], command="create", runner_factory=EndlessRunner) + async with app.run_test() as pilot: + await wait_until(pilot, lambda: app.runner is not None) + # not confirmed: borg keeps running. Enter selects the button that has the focus, the harmless one. + for key in "n", "escape", "enter": + press(app, "q") + await wait_until(pilot, lambda: isinstance(app.screen, ConfirmQuitModal) and app.screen.focused) + assert app.screen.focused.id == "quit-no" + press(app, key) + await wait_until(pilot, lambda: not isinstance(app.screen, ConfirmQuitModal)) + await pilot.pause(0.1) + assert app.is_running and app.session.running and not app.runner.stopped.is_set() + press(app, "q") + await wait_until(pilot, lambda: isinstance(app.screen, ConfirmQuitModal)) + press(app, "y") + await wait_until(pilot, lambda: not app.is_running) + return app + + app = asyncio.run(run()) + assert app.runner.stopped.is_set() # borg was terminated ... + assert app.session.rc == 143 # ... and waited for + + +def test_app_quits_without_confirmation_when_borg_has_finished(monkeypatch): + monkeypatch.setattr(BorgCockpitApp, "QUIT_DELAY", 0) + factory, runners = make_runner_factory([LogMessage(message="done", levelname="INFO")]) + + async def run(): + app = BorgCockpitApp(borg_args=["check"], command="check", runner_factory=factory) + async with app.run_test() as pilot: + await wait_until(pilot, lambda: not app.session.running) + press(app, "q") + await wait_until(pilot, lambda: not app.is_running) # a dialog would keep the app running + return app + + assert asyncio.run(run()).session.rc == 0 + + def test_cockpit_app_create_archive(tmp_path, monkeypatch): if not (is_freebsd or is_win32): pytest.skip("this slow test shall only run on FreeBSD and Windows") @@ -28,21 +472,23 @@ def test_cockpit_app_create_archive(tmp_path, monkeypatch): subprocess.run(["borg", "-r", str(repo_path), "repo-create", "--encryption", "authenticated-sha256"], check=True) async def run(): - app = BorgCockpitApp() - app.borg_args = ["-r", str(repo_path), "create", "--list", "test", str(input_path)] + app = BorgCockpitApp( + borg_args=["-r", str(repo_path), "create", "--list", "test", str(input_path)], command="create" + ) async with app.run_test() as pilot: assert "BorgBackup" in app.TITLE assert app.is_running # Wait for process to finish - while getattr(app, "process_running", True): + while app.session.running: await pilot.pause(0.1) + await pilot.pause(0.5) # let the refresh timer show the final state - status_panel = pilot.app.query_one("#status") - assert status_panel.rc == 0 - - assert app.total_lines_processed > 0 + assert app.session.rc == 0 + assert app.session.count("A") == 5000 + assert app.session.archive_name == "test" # from the --json output + assert app.query_one("#status").shown["status-rc"] == "RC: 0" await pilot.press("q") # quit app