vorta icon indicating copy to clipboard operation
vorta copied to clipboard

Published 20 hours ago • verified publisher icon borgbase

Daily Vorta errors - local exception after client_loop: send disconnect: Broken pipe

Open sammcj opened this issue 2 years ago • 4 comments

Description

Every day I get tens of notifications from Vorta that there's an error during backup creation.

image

Three things I found:

  1. Clicking on the notification does not show any errors or direct you to the logs.

  2. Looking at the logs - they seem to be running at DEBUG level, I can't see where to change this to WARN or ERROR so that the signal to noise ratio is more usable?

  3. I can see through the logs when Vorta thinks there is an interruption in the network rather than retrying or starting another stream the application throws an ERROR and dumps a trace (see logs below).

I have tried Borg and Vorta from homebrew and from pip and the behaviour is the same (although the homebrew version was quite laggy in general I'm assuming due to being an intel only binary).

^

  • 1 (UI/UX issue)
  • 2 (Default configuration issue + maybe a missing option in the UI)
  • 3 (Bug)

Reproduction

  • [X] I tried to reproduce the issue.
  • [X] I was able to reproduce the issue.

OS

macOS, 13.5, 2021 Macbook Pro M1 Pro

Version of Vorta

0.9.0

What did you install Vorta with?

Pip

Version of Borg

1.2.4

Logs

2023-08-12 09:02:32,961 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 1
2023-08-12 09:02:32,961 - vorta.scheduler - INFO - Setting timer for profile 1
2023-08-12 09:02:32,962 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 1
2023-08-12 09:02:32,963 - vorta.scheduler - DEBUG - Catching up by running job for home-base (1)
2023-08-12 09:02:32,965 - vorta.scheduler - INFO - Starting background backup for home-base
2023-08-12 09:02:32,966 - vorta.notifications - DEBUG - success notifications suppressed
2023-08-12 09:02:32,971 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-08-12 09:02:32,971 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-08-12 09:02:32,971 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-08-12 09:02:32,984 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://[email protected]/./repo
2023-08-12 09:02:33,106 - vorta.scheduler - INFO - Preparation for backup successful.
2023-08-12 09:02:33,107 - vorta.borg.jobs_manager - DEBUG - Add job for site 1
2023-08-12 09:02:33,107 - vorta.borg.jobs_manager - DEBUG - Start job on site: 1
2023-08-12 09:02:33,114 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg create --list --progress --info --log-json --json --filter=AM -C lz4 --exclude-from /var/folders/xs/rx231bsdasfg2qj22dm1145gn/T/tmpyira_j5m --exclude-if-present .nobackup ssh://[email protected]/./repo::samm-digio-mbp-2023-08-12-090233 /Users/samm /Volumes/USB-SATA
2023-08-12 09:02:37,183 - vorta.notifications - DEBUG - notification not suppressed
2023-08-12 09:02:37,183 - vorta.scheduler - ERROR - Error during backup creation.
2023-08-12 09:02:37,184 - vorta.scheduler - DEBUG - Paused 1 until 2023-08-12 10:02:37
2023-08-12 09:02:37,184 - vorta.scheduler - DEBUG - Nothing scheduled for profile 1 because of timeout until 2023-08-12 10:02:37.
2023-08-12 09:02:38,695 - vorta.borg.borg_job - INFO - Creating archive at "ssh://[email protected]/./repo::samm-digio-mbp-2023-08-12-090233"
2023-08-12 09:02:41,028 - vorta.borg.borg_job - INFO - Remote: Storage quota: 553.09 GB out of 800.00 GB used.
2023-08-12 09:03:17,234 - vorta.borg.borg_job - WARNING - /Users/samm/Library/Application Support/Knowledge/knowledgeC.db: file changed while we backed it up
2023-08-12 09:12:08,711 - vorta.borg.borg_job - WARNING - Remote: client_loop: send disconnect: Broken pipe
2023-08-12 09:12:08,791 - vorta.borg.borg_job - ERROR - Local Exception
2023-08-12 09:12:08,791 - vorta.borg.borg_job - ERROR - Traceback (most recent call last):
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 183, in wrapper
    return method(self, args, repository=repository, **kwargs)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 675, in do_create
    create_inner(archive, cache, fso)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 608, in create_inner
    self._rec_walk(path=path, parent_fd=parent_fd, name=name,
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 823, in _rec_walk
    self._rec_walk(
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 823, in _rec_walk
    self._rec_walk(
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 823, in _rec_walk
    self._rec_walk(
  [Previous line repeated 3 more times]
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 786, in _rec_walk
    status = self._process_any(path=path, parent_fd=parent_fd, name=name, st=st, fso=fso, cache=cache,
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 688, in _process_any
    return fso.process_file(path=path, parent_fd=parent_fd, name=name, st=st, cache=cache)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archive.py", line 1451, in process_file
    self.process_file_chunks(item, cache, self.stats, self.show_progress, backup_io_iter(self.chunker.chunkify(None, fd)))
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archive.py", line 1273, in process_file_chunks
    item.chunks.append(chunk_processor(chunk))
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archive.py", line 1261, in chunk_processor
    chunk_entry = cache.add_chunk(chunk_id, data, stats, wait=False)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/cache.py", line 951, in add_chunk
    self.repository.put(id, data, wait=wait)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/remote.py", line 476, in do_rpc
    return self.call(f.__name__, named, **extra)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/remote.py", line 711, in call
    for resp in self.call_many(cmd, [args], **kw):
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/remote.py", line 828, in call_many
    raise ConnectionClosed()
borg.remote.ConnectionClosed: Connection closed by remote host

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 5213, in main
    exit_code = archiver.run(args)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 5144, in run
    return set_ec(func(args))
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/archiver.py", line 168, in wrapper
    with repository:
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/remote.py", line 636, in __exit__
    self.rollback()
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/remote.py", line 476, in do_rpc
    return self.call(f.__name__, named, **extra)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/remote.py", line 711, in call
    for resp in self.call_many(cmd, [args], **kw):
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/remote.py", line 781, in call_many
    send_buffer()  # Try to send data, as some cases (async_response) will never try to send data otherwise.
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/remote.py", line 721, in send_buffer
    written = self.ratelimit.write(self.stdin_fd, self.to_send.peek_front())
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.4/libexec/lib/python3.10/site-packages/borg/remote.py", line 417, in write
    written = os.write(fd, to_send)
BrokenPipeError: [Errno 32] Broken pipe

Platform: Darwin samm-digio-mbp.local 22.6.0 Darwin Kernel Version 22.6.0: Wed Jul  5 22:22:05 PDT 2023; root:xnu-8796.141.3~6/RELEASE_ARM64_T6000 arm64
Borg: 1.2.4  Python: CPython 3.10.12 msgpack: 1.0.4 fuse: llfuse 1.4.2 [pyfuse3,llfuse]
PID: 49829  CWD: /
sys.argv: ['/opt/homebrew/bin/borg', 'create', '--list', '--progress', '--info', '--log-json', '--json', '--filter=AM', '-C', 'lz4', '--exclude-from', '/var/folders/xs/sx231bsdasfg2qj22dm1145gn/T/tmpyira_j5m', '--exclude-if-present', '.nobackup', 'ssh://[email protected]/./repo::samm-digio-mbp-2023-08-12-090233', '/Users/samm', '/Volumes/USB-SATA']
SSH_ORIGINAL_COMMAND: None

2023-08-12 09:12:08,919 - vorta.scheduler - DEBUG - Nothing scheduled for profile 1 because of timeout until 2023-08-12 10:02:37.
2023-08-12 09:12:08,919 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 1
2023-08-12 09:12:08,919 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 1
2023-08-12 09:12:12,766 - vorta.notifications - DEBUG - notification not suppressed
2023-08-12 09:12:12,766 - vorta.scheduler - ERROR - Error during backup creation.
2023-08-12 09:12:12,767 - vorta.scheduler - DEBUG - Override existing timeout for profile 1
2023-08-12 09:12:12,767 - vorta.scheduler - DEBUG - Paused 1 until 2023-08-12 10:12:12
2023-08-12 09:12:12,767 - vorta.scheduler - DEBUG - Nothing scheduled for profile 1 because of timeout until 2023-08-12 10:12:12.
2023-08-12 09:32:49,665 - vorta.scheduler - DEBUG - Refreshing all scheduler timers
2023-08-12 09:32:49,678 - vorta.scheduler - DEBUG - Nothing scheduled for profile 1 because of timeout until 2023-08-12 10:12:12.
2023-08-12 09:32:49,682 - vorta.scheduler - INFO - Setting timer for profile 2
2023-08-12 09:32:49,684 - vorta.scheduler - DEBUG - Catching up by running job for git-repos (2)
2023-08-12 09:32:49,686 - vorta.scheduler - INFO - Starting background backup for git-repos
2023-08-12 09:32:49,688 - vorta.notifications - DEBUG - success notifications suppressed
2023-08-12 09:32:49,695 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-08-12 09:32:49,695 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-08-12 09:32:49,695 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-08-12 09:32:49,703 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://[email protected]/./repo
2023-08-12 09:32:49,799 - root - DEBUG - Command ipconfig getpacket en4 failed
2023-08-12 09:32:49,806 - root - DEBUG - Command ipconfig getpacket en5 failed
2023-08-12 09:32:49,810 - root - DEBUG - Command ipconfig getpacket en6 failed
2023-08-12 09:32:49,814 - root - DEBUG - Command ipconfig getpacket bridge0 failed
2023-08-12 09:32:49,822 - root - DEBUG - Command ipconfig getpacket en1 failed
2023-08-12 09:32:49,826 - root - DEBUG - Command ipconfig getpacket en2 failed
2023-08-12 09:32:49,830 - root - DEBUG - Command ipconfig getpacket en3 failed
2023-08-12 09:32:49,856 - vorta.scheduler - INFO - Preparation for backup successful.
2023-08-12 09:32:49,856 - vorta.borg.jobs_manager - DEBUG - Add job for site 2
2023-08-12 09:32:49,857 - vorta.borg.jobs_manager - DEBUG - Start job on site: 2
2023-08-12 09:32:49,859 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg create --list --progress --info --log-json --json --filter=AM -C lz4 --exclude-from /var/folders/xs/sx231bsdasfg2qj22dm1145gn/T/tmpphatccw2 --exclude-if-present .nobackup ssh://[email protected]/./repo::samm-digio-mbp-2023-08-12-093249 /Users/samm/git/sammcj /Users/samm/git/kmart /Users/samm/git/digio
2023-08-12 09:32:55,004 - vorta.borg.borg_job - INFO - Creating archive at "ssh://[email protected]/./repo::samm-digio-mbp-2023-08-12-093249"
2023-08-12 09:32:55,802 - vorta.borg.borg_job - INFO - Remote: Storage quota: 4.96 GB out of 15.00 GB used.
2023-08-12 09:32:56,391 - vorta.borg.borg_job - INFO - Remote: Storage quota: 4.96 GB out of 15.00 GB used.
2023-08-12 09:33:14,292 - vorta.scheduler - INFO - Setting timer for profile 2
2023-08-12 09:33:14,293 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 2
2023-08-12 09:33:14,293 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 2
2023-08-12 09:33:14,294 - vorta.scheduler - DEBUG - Scheduling next run for 2023-08-13 09:00:00
2023-08-12 09:33:18,198 - vorta.notifications - DEBUG - success notifications suppressed
2023-08-12 09:33:18,198 - vorta.scheduler - INFO - Backup creation successful.
2023-08-12 09:33:18,199 - vorta.scheduler - INFO - Doing post-backup jobs for git-repos
2023-08-12 09:33:18,200 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-08-12 09:33:18,200 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-08-12 09:33:18,200 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-08-12 09:33:18,202 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://[email protected]/./repo
2023-08-12 09:33:18,207 - vorta.borg.jobs_manager - DEBUG - Add job for site 2
2023-08-12 09:33:18,207 - vorta.borg.jobs_manager - DEBUG - Start job on site: 2
2023-08-12 09:33:18,208 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-08-12 09:33:18,208 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-08-12 09:33:18,208 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-08-12 09:33:18,208 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg prune --list --info --log-json --keep-hourly 2 --keep-daily 7 --keep-weekly 4 --keep-monthly 6 --keep-yearly 2 -a samm-digio-mbp-* --keep-within 24H ssh://[email protected]/./repo
2023-08-12 09:33:18,214 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://[email protected]/./repo
2023-08-12 09:33:18,214 - vorta.borg.jobs_manager - DEBUG - Add job for site 2
2023-08-12 09:33:18,215 - vorta.scheduler - INFO - Finished background task for profile git-repos
2023-08-12 09:33:18,216 - vorta.scheduler - INFO - Setting timer for profile 2
2023-08-12 09:33:18,216 - vorta.scheduler - DEBUG - Scheduling next run for 2023-08-13 09:00:00
2023-08-12 09:33:23,086 - vorta.borg.borg_job - INFO - Keeping archive (rule: within #1):       samm-digio-mbp-2023-08-12-093249     Sat, 2023-08-12 09:32:55 [8d5007ab444427696373f35f8f40e09126db43cb583aa2a12e33ce1333855d89]
2023-08-12 09:33:23,087 - vorta.borg.borg_job - INFO - Keeping archive (rule: hourly #1):       samm-digio-mbp-2023-08-11-075912     Fri, 2023-08-11 07:59:17 [5698292d204cc5716cd827a709957a83e961a09b1b3abb190c62783f2750cc74]
2023-08-12 09:33:23,087 - vorta.borg.borg_job - INFO - Keeping archive (rule: hourly #2):       samm-digio-mbp-2023-08-10-090000     Thu, 2023-08-10 09:00:05 [6def9582b6d6a8be1c9d8866c80a86d6be8b4a2820df8b4b0b4ea23f8a0bb383]
2023-08-12 09:33:23,087 - vorta.borg.borg_job - INFO - Keeping archive (rule: daily #1):        samm-digio-mbp-2023-08-09-090000     Wed, 2023-08-09 09:00:05 [0e75c214ba0fe63b80ade7c398cf5564486e7b63c3f8ae14e84cbe05dfaf7f76]
2023-08-12 09:33:23,087 - vorta.borg.borg_job - INFO - Keeping archive (rule: daily #2):        samm-digio-mbp-2023-08-08-090000     Tue, 2023-08-08 09:00:05 [3462dec79bf3e3a7bfda25149847f27ccb5f6889136fe9289257c04aeb107e50]
2023-08-12 09:33:23,087 - vorta.borg.borg_job - INFO - Keeping archive (rule: daily #3):        samm-digio-mbp-2023-08-07-090000     Mon, 2023-08-07 09:00:06 [7578425e3537c767a46ab70fd15a767925ad2fd044672bf62bce57759d679497]
2023-08-12 09:33:23,087 - vorta.borg.borg_job - INFO - Keeping archive (rule: daily #4):        samm-digio-mbp-2023-08-06-095517     Sun, 2023-08-06 09:55:22 [85340217c2f8f55acde9dd826ef5d091027a18339a90ffe56db66b2cf89ab086]
2023-08-12 09:33:23,087 - vorta.borg.borg_job - INFO - Keeping archive (rule: daily #5):        samm-digio-mbp-2023-08-05-090211     Sat, 2023-08-05 09:02:17 [5c693a0f9aa88f2b7d7b43c715787f7561419a006d509ba119a9864269f7c4b7]
2023-08-12 09:33:23,087 - vorta.borg.borg_job - INFO - Keeping archive (rule: daily #6):        samm-digio-mbp-2023-08-04-090000     Fri, 2023-08-04 09:00:05 [27d5c2ca9e967cc006dd53c001bc28fa599b5a0141c0875f2b23237cca390d70]
2023-08-12 09:33:23,087 - vorta.borg.borg_job - INFO - Keeping archive (rule: daily #7):        samm-digio-mbp-2023-08-03-085959     Thu, 2023-08-03 09:00:06 [d1e69a0507dde371d4bf1a35ae57b2cc1f68a2c3e21c40a010d13e26dc41ca1c]
2023-08-12 09:33:23,593 - vorta.borg.borg_job - INFO - Remote: Storage quota: 4.96 GB out of 15.00 GB used.
2023-08-12 09:33:23,594 - vorta.borg.borg_job - INFO - Pruning archive (1/2):                   samm-digio-mbp-2023-08-02-090000     Wed, 2023-08-02 09:00:05 [9ef6d1e3c3a5365d87012c81eb3fc52d2387c8dd7afc8109e5cdd44c7da551e1]
2023-08-12 09:33:24,099 - vorta.borg.borg_job - INFO - Pruning archive (2/2):                   samm-digio-mbp-2023-08-01-085959     Tue, 2023-08-01 09:00:05 [4fc8eb347c880db0964515ff66f5b317304522002bd677c4f1b57a72b3a7b33c]
2023-08-12 09:33:24,100 - vorta.borg.borg_job - INFO - Keeping archive (rule: monthly #1):      samm-digio-mbp-2023-07-31-085959     Mon, 2023-07-31 09:00:05 [70dcf1eab9518c4b995acd11b213a9e391c70e532c80ab06d955ed9726f8cc79]
2023-08-12 09:33:24,100 - vorta.borg.borg_job - INFO - Keeping archive (rule: weekly #1):       samm-digio-mbp-2023-07-30-093009     Sun, 2023-07-30 09:30:14 [1547c2e4e893f8611e3ff4efd68764f9054a01ba8ad88bc24663886dc8966e7f]
2023-08-12 09:33:24,100 - vorta.borg.borg_job - INFO - Keeping archive (rule: weekly[oldest] #2): samm-digio-mbp-2023-07-26-090005     Wed, 2023-07-26 09:00:11 [9dfb919e0008d0be02c2d5d5dcdbf4a049cfa0aacf46fc0c902250d63f426e1e]
2023-08-12 09:33:25,133 - vorta.borg.borg_job - INFO - Remote: Storage quota: 4.96 GB out of 15.00 GB used.
2023-08-12 09:33:25,797 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 2
2023-08-12 09:33:25,799 - vorta.scheduler - INFO - Setting timer for profile 2
2023-08-12 09:33:25,799 - vorta.borg.jobs_manager - DEBUG - Start job on site: 2
2023-08-12 09:33:25,801 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg list --info --log-json --json ssh://[email protected]/./repo
2023-08-12 09:33:25,814 - vorta.scheduler - DEBUG - Scheduling next run for 2023-08-13 09:00:00
2023-08-12 09:33:31,114 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 2
2023-08-12 09:33:31,115 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 2
2023-08-12 09:33:31,115 - vorta.scheduler - INFO - Setting timer for profile 2
2023-08-12 09:33:31,116 - vorta.scheduler - DEBUG - Scheduling next run for 2023-08-13 09:00:00

Looking through macOS's system configd logs for the network interfaces, there's the normal route refresh that happens that's around the time that vorta crashes:


2023-08-12 08:45:39.298970+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net ::/0 Gate fe80::redactedipv6 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 08:45:39.298977+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net 2403:redactedipv6::/48 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 08:45:39.298981+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net fe80::/64 Ifp en7 [kern] [force]
2023-08-12 08:45:39.301248+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en7:192.168.0.199, en0) v6(en7:2403:redactedipv6, en0) DNS Proxy SMB
2023-08-12 08:45:39.415659+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] setting hostname to "samm-digio-mbp.localdomain"
2023-08-12 09:02:32.422101+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] setting hostname to "samm-digio-mbp.local"
2023-08-12 09:02:32.425685+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] IPv4 over en0 (rank 0x1000006) demoted: primary IPv6 en7 (rank 0x1000005)
2023-08-12 09:02:32.433372+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v6(en7:2403:redactedipv6, en0) DNS! Proxy SMB
2023-08-12 09:02:32.562876+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en0!:192.168.0.169) v6(en0:2403:redactedipv6::1038) DNS! Proxy! SMB+
2023-08-12 09:02:32.606222+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] IPv6 over en0 (rank 0x1000006) demoted: primary IPv4 en7 (rank 0x1000005)
2023-08-12 09:02:32.618442+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en7+:192.168.0.199, en0) DNS! Proxy! SMB-
2023-08-12 09:02:32.813377+1000 0xa12880   configd: [com.apple.SystemConfiguration:IPMonitor] Publishing data to agent DNSAgent-_defaultDNS (106 bytes)
2023-08-12 09:02:32.813733+1000 0xa12880   configd: [com.apple.SystemConfiguration:IPMonitor] Publishing data to agent DNSAgent-@en7 (106 bytes)
2023-08-12 09:02:32.986427+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] setting hostname to "samm-digio-mbp.localdomain"
2023-08-12 09:02:33.366485+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en7:192.168.0.199, en0) v6(en7+:2403:redactedipv6, en0!:2403:redactedipv6::1038) DNS! Proxy SMB
2023-08-12 09:02:33.631816+1000 0xa12853   configd: [com.apple.SystemConfiguration:IPMonitor] Publishing data to agent DNSAgent-_defaultDNS (146 bytes)
2023-08-12 09:02:33.632142+1000 0xa12853   configd: [com.apple.SystemConfiguration:IPMonitor] Publishing data to agent DNSAgent-@en7 (146 bytes)
2023-08-12 09:02:33.641222+1000 0xa12851   configd: [com.apple.SystemConfiguration:IPMonitor] en7: nat64 prefix unavailable
2023-08-12 09:02:33.641279+1000 0xa12851   configd: [com.apple.SystemConfiguration:IPMonitor] en7: nat64 prefixes updated
2023-08-12 09:02:33.649585+1000 0xa12851   configd: [com.apple.SystemConfiguration:IPMonitor] en7: PLAT discovery complete {
    PLATDiscoveryCompletionTime = "2023-08-11 23:02:33 +0000";
    PLATDiscoveryStartTime = "2023-08-11 23:02:33 +0000";
}
2023-08-12 09:02:33.659237+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net ::/0 Gate fe80::redactedipv6 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 09:02:33.659242+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net 2403:redactedipv6::/48 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 09:02:33.659245+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net fe80::/64 Ifp en7 [kern] [force]
2023-08-12 09:02:33.660605+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en7:192.168.0.199, en0) v6(en7:2403:redactedipv6, en0) DNS Proxy SMB
2023-08-12 09:12:06.712110+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] setting hostname to "samm-digio-mbp.local"
2023-08-12 09:12:06.712882+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] IPv4 over en0 (rank 0x1000006) demoted: primary IPv6 en7 (rank 0x1000005)
2023-08-12 09:12:06.717059+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v6(en7!:2403:redactedipv6, en0) DNS- Proxy SMB
2023-08-12 09:12:07.763181+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en7+:192.168.0.199, en0!:192.168.0.169) v6(en7!:2403:redactedipv6, en0) DNS+ Proxy SMB
2023-08-12 09:12:07.803884+1000 0xa12713   configd: [com.apple.SystemConfiguration:IPMonitor] Publishing data to agent DNSAgent-_defaultDNS (146 bytes)
2023-08-12 09:12:07.804101+1000 0xa12713   configd: [com.apple.SystemConfiguration:IPMonitor] Publishing data to agent DNSAgent-@en7 (146 bytes)
2023-08-12 09:12:08.191163+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net ::/0 Gate fe80::redactedipv6 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 09:12:08.191169+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net 2403:redactedipv6::/48 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 09:12:08.191173+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net fe80::/64 Ifp en7 [kern] [force]
2023-08-12 09:12:08.194433+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en7:192.168.0.199, en0) v6(en7:2403:redactedipv6, en0) DNS Proxy SMB
2023-08-12 09:12:08.716448+1000 0xa12713   configd: [com.apple.SystemConfiguration:IPMonitor] en7: nat64 prefix unavailable
2023-08-12 09:12:08.716585+1000 0xa12713   configd: [com.apple.SystemConfiguration:IPMonitor] en7: nat64 prefixes updated
2023-08-12 09:12:08.719136+1000 0xa12713   configd: [com.apple.SystemConfiguration:IPMonitor] en7: PLAT discovery complete {
    PLATDiscoveryCompletionTime = "2023-08-11 23:12:08 +0000";
    PLATDiscoveryStartTime = "2023-08-11 23:12:08 +0000";
}
2023-08-12 09:12:08.728576+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net ::/0 Gate fe80::redactedipv6 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 09:12:08.728584+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net 2403:redactedipv6::/48 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 09:12:08.728589+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net fe80::/64 Ifp en7 [kern] [force]
2023-08-12 09:12:08.731691+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en7:192.168.0.199, en0) v6(en7:2403:redactedipv6, en0) DNS Proxy SMB
2023-08-12 09:12:08.919795+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] setting hostname to "samm-digio-mbp.localdomain"
2023-08-12 09:13:07.121197+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] setting hostname to "samm-digio-mbp.local"
2023-08-12 09:13:07.123190+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] IPv4 over en0 (rank 0x1000006) demoted: primary IPv6 en7 (rank 0x1000005)
2023-08-12 09:13:07.127455+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v6(en7!:2403:redactedipv6, en0) DNS- Proxy SMB
2023-08-12 09:13:08.153174+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en7+:192.168.0.199, en0!:192.168.0.169) v6(en7!:2403:redactedipv6, en0) DNS+ Proxy SMB
2023-08-12 09:13:08.241707+1000 0xa13964   configd: [com.apple.SystemConfiguration:IPMonitor] Publishing data to agent DNSAgent-_defaultDNS (146 bytes)
2023-08-12 09:13:08.242119+1000 0xa13964   configd: [com.apple.SystemConfiguration:IPMonitor] Publishing data to agent DNSAgent-@en7 (146 bytes)
2023-08-12 09:13:08.628855+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net ::/0 Gate fe80::redactedipv6 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 09:13:08.628862+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net 2403:redactedipv6::/48 Ifp en7 Ifa 2403:redactedipv6 [kern] [force]
2023-08-12 09:13:08.628866+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] Re-applying route: Net fe80::/64 Ifp en7 [kern] [force]
2023-08-12 09:13:08.631967+1000 0xe34      configd: [com.apple.SystemConfiguration:IPMonitor] network changed: v4(en7:192.168.0.199, en0) v6(en7:2403:redactedipv6, en0) DNS Proxy SMB
2023-08-12 09:13:08.654328+1000 0xa1384e   configd: [com.apple.SystemConfiguration:IPMonitor] en7: nat64 prefix unavailable
2023-08-12 09:13:08.655019+1000 0xa1384e   configd: [com.apple.SystemConfiguration:IPMonitor] en7: nat64 prefixes updated
2023-08-12 09:13:08.655255+1000 0xa1384e   configd: [com.apple.SystemConfiguration:IPMonitor] en7: PLAT discovery complete {
    PLATDiscoveryCompletionTime = "2023-08-11 23:13:08 +0000";
    PLATDiscoveryStartTime = "2023-08-11 23:13:08 +0000";
}

sammcj avatar Aug 12 '23 00:08 sammcj

Looks like everything works, but the network breaks in the middle. Is the laptop going to sleep maybe or disconnecting Wifi?

borg.remote.ConnectionClosed: Connection closed by remote host

m3nu avatar Aug 12 '23 08:08 m3nu

Highly likely if Vorta doesn’t prevent a sleep when a backup is in progress.

It shouldn’t throw tons of errors like this just because your laptop goes to sleep should it?

sammcj avatar Aug 12 '23 09:08 sammcj

Three things I found:

  1. Clicking on the notification does not show any errors or direct you to the logs.

  2. Looking at the logs - they seem to be running at DEBUG level, I can't see where to change this to WARN or ERROR so that the signal to noise ratio is more usable?

  3. I can see through the logs when Vorta thinks there is an interruption in the network rather than retrying or starting another stream the application throws an ERROR and dumps a trace (see logs below).

I aggree that all three points are issues. Point 1 should be tracked in a seperate issue and needs #1522 to be completed. For 2 we are already planning to add a log viewer to Vorta that should include such a feature. For 3 there is #1444 and #1420.

real-yfprojects avatar Aug 13 '23 12:08 real-yfprojects

This happened to me too while doing an initial backup to BorgBase. It occurred numerous times while I was actively using my computer so I don't think it's just from sleep or inactivity on the client side.

m1k3s0 avatar Aug 17 '23 19:08 m1k3s0

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

github-actions[bot] avatar Apr 10 '24 02:04 github-actions[bot]

Closing as gave up on using Vorta

sammcj avatar Apr 10 '24 02:04 sammcj