Error: Connection closed by remote host - when backing up to BorgBase

[andreagrandi]

Description

Hello folks, tonight I ran my first scheduled backup at 1:00 AM and this morning I checked logs to see if everything was fine. It looks like the backup was eventually completed, but I initially got a Error: Connection closed by remote host.

I'm not sure why this happened, but I would like to find out because a scheduled backup should just work, I shouldn't be checking every morning if it ran or not.

p.s: in the logs I replaced my real connection string with ******.

Cheers

Reproduction

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

OS

MacOS 14.2.1

Version of Vorta

0.8.11

What did you install Vorta with?

Homebrew

Version of Borg

1.2.6

Logs

2023-12-27 00:58:02,630 - vorta.scheduler - DEBUG - Scheduling next run for 2023-12-27 01:00:00
2023-12-27 00:59:59,613 - vorta.scheduler - INFO - Starting background backup for pCrypto (BorgBase)
2023-12-27 00:59:59,616 - vorta.notifications - DEBUG - success notifications suppressed
2023-12-27 00:59:59,621 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-12-27 00:59:59,621 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-12-27 00:59:59,621 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-12-27 00:59:59,630 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://****.repo.borgbase.com/./repo
2023-12-27 00:59:59,756 - root - DEBUG - Command ipconfig getpacket en4 failed
2023-12-27 00:59:59,766 - root - DEBUG - Command ipconfig getpacket en5 failed
2023-12-27 00:59:59,776 - root - DEBUG - Command ipconfig getpacket en6 failed
2023-12-27 00:59:59,785 - root - DEBUG - Command ipconfig getpacket bridge0 failed
2023-12-27 00:59:59,804 - root - DEBUG - Command ipconfig getpacket en1 failed
2023-12-27 00:59:59,814 - root - DEBUG - Command ipconfig getpacket en2 failed
2023-12-27 00:59:59,824 - root - DEBUG - Command ipconfig getpacket en3 failed
2023-12-27 00:59:59,825 - vorta.scheduler - INFO - Preparation for backup successful.
2023-12-27 00:59:59,825 - vorta.borg.jobs_manager - DEBUG - Add job for site 4
2023-12-27 00:59:59,825 - vorta.borg.jobs_manager - DEBUG - Start job on site: 4
2023-12-27 00:59:59,833 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg create --list --progress --info --log-json --json --filter=AM -C lz4 ssh://*****.repo.borgbase.com/./repo::Andreas-MacBook-Pro-M2.local-2023-12-27-005959 /Users/andrea/pCrypto
2023-12-27 01:00:02,318 - vorta.borg.borg_job - INFO - Creating archive at "ssh://*********.repo.borgbase.com/./repo::Andreas-MacBook-Pro-M2.local-2023-12-27-005959"
2023-12-27 01:16:19,613 - vorta.borg.borg_job - WARNING - Remote: client_loop: send disconnect: Broken pipe
2023-12-27 01:16:19,619 - vorta.borg.borg_job - ERROR - Connection closed by remote host
2023-12-27 01:16:19,744 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 4
2023-12-27 01:16:19,745 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 4
2023-12-27 01:16:19,746 - vorta.scheduler - INFO - Setting timer for profile 2
2023-12-27 01:16:19,747 - vorta.scheduler - DEBUG - Catching up by running job for pCrypto (BorgBase) (2)
2023-12-27 01:16:19,749 - vorta.scheduler - INFO - Starting background backup for pCrypto (BorgBase)
2023-12-27 01:16:19,750 - vorta.notifications - DEBUG - success notifications suppressed
2023-12-27 01:16:19,751 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-12-27 01:16:19,751 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-12-27 01:16:19,751 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-12-27 01:16:19,756 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://*******.repo.borgbase.com/./repo
2023-12-27 01:16:19,850 - root - DEBUG - Command ipconfig getpacket en4 failed
2023-12-27 01:16:19,860 - root - DEBUG - Command ipconfig getpacket en5 failed
2023-12-27 01:16:19,870 - root - DEBUG - Command ipconfig getpacket en6 failed
2023-12-27 01:16:19,880 - root - DEBUG - Command ipconfig getpacket bridge0 failed
2023-12-27 01:16:19,899 - root - DEBUG - Command ipconfig getpacket en1 failed
2023-12-27 01:16:19,909 - root - DEBUG - Command ipconfig getpacket en2 failed
2023-12-27 01:16:19,919 - root - DEBUG - Command ipconfig getpacket en3 failed
2023-12-27 01:16:19,920 - vorta.scheduler - INFO - Preparation for backup successful.
2023-12-27 01:16:19,921 - vorta.borg.jobs_manager - DEBUG - Add job for site 4
2023-12-27 01:16:19,921 - vorta.borg.jobs_manager - DEBUG - Start job on site: 4
2023-12-27 01:16:19,945 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg create --list --progress --info --log-json --json --filter=AM -C lz4 ssh://**********.repo.borgbase.com/./repo::Andreas-MacBook-Pro-M2.local-2023-12-27-011619 /Users/andrea/pCrypto
2023-12-27 01:16:20,029 - vorta.notifications - DEBUG - notification not suppressed
2023-12-27 01:16:20,030 - vorta.scheduler - ERROR - Error during backup creation.
2023-12-27 01:16:20,031 - vorta.scheduler - DEBUG - Paused 2 until 2023-12-27 02:16:20
2023-12-27 01:16:20,031 - vorta.scheduler - DEBUG - Nothing scheduled for profile 2 because of timeout until 2023-12-27 02:16:20.
2023-12-27 01:16:21,900 - vorta.borg.borg_job - INFO - Creating archive at "ssh://**********.repo.borgbase.com/./repo::Andreas-MacBook-Pro-M2.local-2023-12-27-011619"
2023-12-27 01:17:39,160 - vorta.borg.borg_job - INFO - Remote: Storage quota: 18.29 GB out of 1.00 TB used.
2023-12-27 01:18:11,013 - vorta.borg.borg_job - INFO - Remote: Storage quota: 18.47 GB out of 1.00 TB used.
2023-12-27 01:18:11,479 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 4
2023-12-27 01:18:11,479 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 4
2023-12-27 01:18:11,480 - vorta.scheduler - DEBUG - Nothing scheduled for profile 2 because of timeout until 2023-12-27 02:16:20.
2023-12-27 01:18:11,626 - vorta.notifications - DEBUG - success notifications suppressed
2023-12-27 01:18:11,626 - vorta.scheduler - INFO - Backup creation successful.
2023-12-27 01:18:11,626 - vorta.scheduler - DEBUG - Unpaused 2
2023-12-27 01:18:11,627 - vorta.scheduler - INFO - Setting timer for profile 2
2023-12-27 01:18:11,627 - vorta.scheduler - DEBUG - Scheduling next run for 2023-12-28 01:00:00
2023-12-27 01:18:11,629 - vorta.scheduler - INFO - Doing post-backup jobs for pCrypto (BorgBase)
2023-12-27 01:18:11,629 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-12-27 01:18:11,630 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-12-27 01:18:11,630 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-12-27 01:18:11,632 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://**********.repo.borgbase.com/./repo
2023-12-27 01:18:11,632 - vorta.borg.jobs_manager - DEBUG - Add job for site 4
2023-12-27 01:18:11,632 - vorta.borg.jobs_manager - DEBUG - Start job on site: 4
2023-12-27 01:18:11,633 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-12-27 01:18:11,633 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-12-27 01:18:11,633 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-12-27 01:18:11,634 - 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 Andreas-MacBook-Pro-M2.local-* --keep-within 10H ssh://*********.repo.borgbase.com/./repo
2023-12-27 01:18:11,640 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://********.repo.borgbase.com/./repo
2023-12-27 01:18:11,641 - vorta.borg.jobs_manager - DEBUG - Add job for site 4
2023-12-27 01:18:11,643 - vorta.keyring.abc - DEBUG - No module named 'secretstorage'
2023-12-27 01:18:11,643 - vorta.keyring.abc - DEBUG - Using VortaDarwinKeyring
2023-12-27 01:18:11,643 - vorta.borg.borg_job - DEBUG - Using VortaDarwinKeyring keyring to store passwords.
2023-12-27 01:18:11,645 - vorta.keyring.darwin - DEBUG - Retrieved password for repo ssh://*********.repo.borgbase.com/./repo
2023-12-27 01:18:11,645 - vorta.borg.jobs_manager - DEBUG - Add job for site 4
2023-12-27 01:18:11,645 - vorta.scheduler - INFO - Finished background task for profile pCrypto (BorgBase)
2023-12-27 01:18:11,646 - vorta.scheduler - INFO - Setting timer for profile 2
2023-12-27 01:18:11,646 - vorta.scheduler - DEBUG - Scheduling next run for 2023-12-28 01:00:00
2023-12-27 01:18:13,319 - vorta.borg.borg_job - INFO - Keeping archive (rule: within #1):       Andreas-MacBook-Pro-M2.local-2023-12-27-011619 Wed, 2023-12-27 01:16:21 [e26065faf9566183cd7a4e9dff10ac348a526753e9c491bae72ad4f433b3be26]
2023-12-27 01:18:13,319 - vorta.borg.borg_job - INFO - Keeping archive (rule: within #2):       Andreas-MacBook-Pro-M2.local-2023-12-26-175019 Tue, 2023-12-26 17:50:21 [4590ef3ddacd64bc1d63e9a57c46d66eefbdadaa95462391736913e0fc7ba8d2]
2023-12-27 01:18:13,533 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 4
2023-12-27 01:18:13,535 - vorta.borg.jobs_manager - DEBUG - Start job on site: 4
2023-12-27 01:18:13,535 - vorta.scheduler - INFO - Setting timer for profile 2
2023-12-27 01:18:13,537 - vorta.scheduler - DEBUG - Scheduling next run for 2023-12-28 01:00:00
2023-12-27 01:18:13,537 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg list --info --log-json --json ssh://*********.repo.borgbase.com/./repo
2023-12-27 01:18:15,416 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 4
2023-12-27 01:18:15,418 - vorta.scheduler - INFO - Setting timer for profile 2
2023-12-27 01:18:15,418 - vorta.borg.jobs_manager - DEBUG - Start job on site: 4
2023-12-27 01:18:15,421 - vorta.scheduler - DEBUG - Scheduling next run for 2023-12-28 01:00:00
2023-12-27 01:18:15,421 - vorta.borg.borg_job - INFO - Running command /opt/homebrew/bin/borg check --info --log-json --progress ssh://**********.repo.borgbase.com/./repo
2023-12-27 01:18:17,066 - vorta.borg.borg_job - INFO - Remote: Starting repository check
2023-12-27 01:19:44,393 - vorta.borg.borg_job - INFO - Remote: finished segment check at segment 43
2023-12-27 01:19:44,394 - vorta.borg.borg_job - INFO - Remote: Starting repository index check
2023-12-27 01:19:44,394 - vorta.borg.borg_job - INFO - Remote: Index object count match.
2023-12-27 01:19:44,396 - vorta.borg.borg_job - INFO - Remote: Finished full repository check, no problems found.
2023-12-27 01:19:44,396 - vorta.borg.borg_job - INFO - Starting archive consistency check...
2023-12-27 01:19:45,246 - vorta.borg.borg_job - INFO - Analyzing archive Andreas-MacBook-Pro-M2.local-2023-12-26-175019 (1/2)
2023-12-27 01:19:45,725 - vorta.borg.borg_job - INFO - Analyzing archive Andreas-MacBook-Pro-M2.local-2023-12-27-011619 (2/2)
2023-12-27 01:19:46,104 - vorta.borg.borg_job - INFO - Archive consistency check complete, no problems found.
2023-12-27 01:19:47,395 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 4
2023-12-27 01:19:47,396 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 4

[m3nu]

Usually a connection issue or hibernation. Since this is a laptop, you're likely on a residential internet connection. Those are usually less reliable than a data center. If this happens, Borg will continue the next time from the latest checkpoint archive it made. By default those are added every 30min.

More: https://docs.borgbase.com/faq/#my-ssh-connection-breaks-after-a-long-backup-or-prune-operation

[andreagrandi]

Hi, I think the connection was fine (I didn't find any disconnects in router logs) but I suspect the laptop didn't wake up in time. What should I do in MacOS, to make sure the laptop wakes up correctly when it needs to backup? Please note that it's constantly connected to the power. Thanks

[andreagrandi]

I just had another similar error, this time the laptop wasn't sleeping. I configured a new backup and manually triggered it. After a little bit I came back to my laptop and found this:

2023-12-27 18:14:03,497 - vorta.borg.borg_job - WARNING - Remote: client_loop: send disconnect: Broken pipe
2023-12-27 18:14:03,509 - vorta.borg.borg_job - ERROR - Local Exception
2023-12-27 18:14:03,509 - vorta.borg.borg_job - ERROR - Traceback (most recent call last):
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 183, in wrapper
    return method(self, args, repository=repository, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 664, in do_create
    create_inner(archive, cache, fso)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 597, in create_inner
    self._rec_walk(path=path, parent_fd=None, name=None,
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 812, in _rec_walk
    self._rec_walk(
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 812, in _rec_walk
    self._rec_walk(
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 812, in _rec_walk
    self._rec_walk(
  [Previous line repeated 1 more time]
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 775, 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.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 677, 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.6/libexec/lib/python3.11/site-packages/borg/archive.py", line 1455, 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.6/libexec/lib/python3.11/site-packages/borg/archive.py", line 1277, in process_file_chunks
    item.chunks.append(chunk_processor(chunk))
                       ^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archive.py", line 1265, in chunk_processor
    chunk_entry = cache.add_chunk(chunk_id, data, stats, wait=False)
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/cache.py", line 952, in add_chunk
    self.repository.put(id, data, wait=wait)
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/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.6/libexec/lib/python3.11/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.6/libexec/lib/python3.11/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.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 5324, in main
    exit_code = archiver.run(args)
                ^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 5255, in run
    return set_ec(func(args))
                  ^^^^^^^^^^
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/archiver.py", line 168, in wrapper
    with repository:
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/site-packages/borg/remote.py", line 636, in __exit__
    self.rollback()
  File "/opt/homebrew/Cellar/borgbackup-fuse/1.2.6/libexec/lib/python3.11/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.6/libexec/lib/python3.11/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.6/libexec/lib/python3.11/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.6/libexec/lib/python3.11/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.6/libexec/lib/python3.11/site-packages/borg/remote.py", line 417, in write
    written = os.write(fd, to_send)
              ^^^^^^^^^^^^^^^^^^^^^
BrokenPipeError: [Errno 32] Broken pipe

Platform: Darwin Andreas-MacBook-Pro-M2.local 23.2.0 Darwin Kernel Version 23.2.0: Wed Nov 15 21:55:06 PST 2023; root:xnu-10002.61.3~2/RELEASE_ARM64_T6020 arm64
Borg: 1.2.6  Python: CPython 3.11.6 msgpack: 1.0.5 fuse: llfuse 1.5.0 [pyfuse3,llfuse]
PID: 72776  CWD: /
sys.argv: ['/opt/homebrew/bin/borg', 'create', '--list', '--progress', '--info', '--log-json', '--json', '--filter=AM', '-C', 'lz4', 'ssh://[email protected]/./repo::Andreas-MacBook-Pro-M2.local-2023-12-27-174044', '/Users/andrea/Documents', '/Users/andrea/Projects', '/Users/andrea/Music', '/Users/andrea/.ssh']
SSH_ORIGINAL_COMMAND: None

2023-12-27 18:14:03,641 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 6
2023-12-27 18:14:03,643 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 6

The errors seem to come from borg, should I open an issue on their repository?

[real-yfprojects]

The errors seem to come from borg, should I open an issue on their repository?

Yes, this is probably an issue with borg.

[github-actions[bot]]

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]]

This issue was closed because it has been stalled for 7 days with no activity.