Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
2 tasks done
sammcj opened this issue Aug 12, 2023 · 6 comments
Closed
2 tasks done

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

sammcj opened this issue Aug 12, 2023 · 6 comments
Labels
status:stale This item will be closed soon due to inactivity type:support A question about using vorta

Comments

@sammcj
Copy link
Contributor

sammcj commented Aug 12, 2023 •
edited

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

  • I tried to reproduce the issue.
  • 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://redacted@redacted.repo.borgbase.com/./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://redacted@redacted.repo.borgbase.com/./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://redacted@redacted.repo.borgbase.com/./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://redacted@redacted.repo.borgbase.com/./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://redacted@redacted.repo.borgbase.com/./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://redacted@redacted.repo.borgbase.com/./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://redacted@redacted.repo.borgbase.com/./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://redacted@redacted.repo.borgbase.com/./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://redacted@redacted.repo.borgbase.com/./repo
2023-08-12 09:33:18,214 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://redacted@redacted.repo.borgbase.com/./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://redacted@redacted.repo.borgbase.com/./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";
}
@m3nu
Copy link
Contributor

m3nu commented Aug 12, 2023

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 m3nu added the type:support A question about using vorta label Aug 12, 2023
@sammcj
Copy link
Contributor Author

sammcj commented Aug 12, 2023

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?

@real-yfprojects
Copy link
Collaborator

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.

@sammcj sammcj mentioned this issue Aug 13, 2023
Draft
@m1k3s0
Copy link

m1k3s0 commented Aug 17, 2023

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.

@real-yfprojects real-yfprojects mentioned this issue Sep 1, 2023
Open
@github-actions GitHub Actions
Copy link

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 github-actions bot added the status:stale This item will be closed soon due to inactivity label Apr 10, 2024
@sammcj
Copy link
Contributor Author

sammcj commented Apr 10, 2024

Closing as gave up on using Vorta

@sammcj sammcj closed this as completed Apr 10, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
status:stale This item will be closed soon due to inactivity type:support A question about using vorta
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@sammcj @m3nu @m1k3s0 @real-yfprojects