Error during borg create after changing base directory and user

[rcdailey]

On my Synology NAS, I was running borgmatic as the root user. I switched the task to a non-root user instead. However, I get failures when I run borgmatic --create --prune (see below).

I moved the entire borg directory & files to a new location and did chmod & chown to switch the user and permissions.

I'm not sure why I still get this failure. Borg is very difficult to use with mysterious errors and no clear way to recover from them. I'm at the end of my rope.

summary:
/volume2/BorgBackup/borgmatic.yml: Error running configuration file
snip.repo.borgbase.com:repo: Error running actions for repository
...
Remote: Initialized logging system for JSON-based protocol
Remote: Resolving repository path b'repo'
Remote: Resolved repository path to '/srv/repos/snip/repo'
Remote: Verified integrity of /srv/repos/snip/repo/index.3961
TAM-verified manifest
security: read previous location 'ssh://snip.repo.borgbase.com/./repo'
security: read manifest timestamp '2022-05-31T20:10:23.649482'
security: determined newest manifest timestamp as 2022-05-31T20:10:23.649482
security: repository checks ok, allowing access
Creating archive at "snip.repo.borgbase.com:repo::diskstation-2022-05-31T15:10:27.383495"
Verified integrity of /volume2/BorgBackup/.borg/.cache/borg/2d931852622812096ee5dec8e4e6b12b2d272e4f3c1f9e7ec694380368686f30/chunks
Reading files cache ...
Verified integrity of /volume2/BorgBackup/.borg/.cache/borg/2d931852622812096ee5dec8e4e6b12b2d272e4f3c1f9e7ec694380368686f30/files
security: read previous location 'ssh://snip.repo.borgbase.com/./repo'
security: read manifest timestamp '2022-05-31T20:10:23.649482'
security: determined newest manifest timestamp as 2022-05-31T20:10:23.649482
security: repository checks ok, allowing access
Processing files ...
Remote: Cleaned up 0 uncommitted segment files (== everything after segment 3961).
Remote: Verified integrity of /srv/repos/snip/repo/hints.3961
Remote: Storage quota: 867.42 GB out of 3.95 TB used.
RemoteRepository: 217.64 MB bytes sent, 8.51 kB bytes received, 453 messages sent
Local Exception
Traceback (most recent call last):
  File "/volume2/@appstore/borgbackup/env/lib/python3.10/site-packages/borg/helpers/fs.py", line 290, in os_open
Command 'borg create --exclude-from /tmp/tmpws6g1vs1 --debug --show-rc snip.repo.borgbase.com:repo::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f} /volume2/homes/user1 /volume2/nextcloud/user2/files /volume2/nextcloud/user1/files' returned non-zero exit status 2.

Need some help? https://torsion.org/borgmatic/#issues

The YAML I use is:

location:
  repositories:
    - snip.repo.borgbase.com:repo
  source_directories:
    - /volume2/homes/user1
    - /volume2/nextcloud/user1/files
    - /volume2/nextcloud/user2/files
  exclude_patterns:
    - /volume2/homes/user1/Google Drive Backup

storage:
  ssh_command: ssh -i /volume2/BorgBackup/id_synology_borgbase
  encryption_passphrase: "snip"
  borg_base_directory: /volume2/BorgBackup/.borg

retention:
  keep_daily: 7
  keep_weekly: 4
  keep_monthly: 6

consistency:
  checks:
    - repository

[ThomasWaldmann]

I can't help you with borgmatic, but the traceback seen above is incomplete (usually one should see the specific file name for which the os_open fails).

Maybe check if the source_directories you give all actually exist. See also there: #6374

In general, if you switch users and also force borg to use the same base directory, you create a permissions mixup which you have to fix manually.

[rcdailey]

Yes your advice makes perfect sense. I should have mentioned I'm only doing backups once as one user on this machine. So it should be ok in this case, right?

I will try the command you provided and let you know how it goes.

[rcdailey]

I cleared the cache but after a few hours, it still failed the same way. I'm not sure if this is a borg issue or a Synology one. It seems to work better when I run it directly via SSH (as the same user) versus as a Scheduled Task in the DSM control panel (again, set up to use that same user).

[ThomasWaldmann]

Does the scheduled task run borg as the same user?

[rcdailey]

Yes it does. Looks like I was mistaken, same failure regardless how I run it. Here's the latest failure info. Sorry to just dump this on you. I'm honestly not sure how to resolve the issue. I did try to comb through the logs for anything obvious.

I'm not sure if these logs have sensitive information in them. If so just let me know and I'll edit.

borg create --exclude-from /tmp/tmp9m68h84p --compression zstd --debug --show-rc --debug c5q0guvb@c5q0guvb.repo.borgbase.com:repo::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f} /volume2/homes/robert /volume2/nextcloud/jennifer/files /volume2/nextcloud/robert/files
using builtin fallback logging configuration
38 self tests completed in 0.27 seconds
SSH command line: ['ssh', '-i', '/volume2/BorgBackup/id_synology_borgbase', 'c5q0guvb@c5q0guvb.repo.borgbase.com', 'borg', 'serve', '--debug']
Remote: using builtin fallback logging configuration
Remote: borg selftest disabled via BORG_SELFTEST env variable
Remote: using builtin fallback logging configuration
Remote: Initialized logging system for JSON-based protocol
Remote: Resolving repository path b'repo'
Remote: Resolved repository path to '/srv/repos/c5q0guvb/repo'
Remote: Verified integrity of /srv/repos/c5q0guvb/repo/index.4021
TAM-verified manifest
security: read previous location 'ssh://c5q0guvb@c5q0guvb.repo.borgbase.com/./repo'
security: read manifest timestamp '2022-06-02T13:47:38.881875'
security: determined newest manifest timestamp as 2022-06-02T13:47:38.881875
security: repository checks ok, allowing access
Creating archive at "c5q0guvb@c5q0guvb.repo.borgbase.com:repo::diskstation-2022-06-02T08:47:49.260208"
Verified integrity of /volume2/BorgBackup/.borg/.cache/borg/2d931852622812096ee5dec8e4e6b12b2d272e4f3c1f9e7ec694380368686f30/chunks
Reading files cache ...
Verified integrity of /volume2/BorgBackup/.borg/.cache/borg/2d931852622812096ee5dec8e4e6b12b2d272e4f3c1f9e7ec694380368686f30/files
security: read previous location 'ssh://c5q0guvb@c5q0guvb.repo.borgbase.com/./repo'
security: read manifest timestamp '2022-06-02T13:47:38.881875'
security: determined newest manifest timestamp as 2022-06-02T13:47:38.881875
security: repository checks ok, allowing access
Processing files ...
Remote: Cleaned up 0 uncommitted segment files (== everything after segment 4021).
Remote: Verified integrity of /srv/repos/c5q0guvb/repo/hints.4021
Remote: Storage quota: 867.44 GB out of 3.95 TB used.
/volume2/homes/robert/LogCenter/SYNOSYSLOGDB__ARCH.DB-shm: file changed while we backed it up
RemoteRepository: 192.51 MB bytes sent, 7.07 kB bytes received, 292 messages sent
Local Exception
Traceback (most recent call last):
  File "/volume2/@appstore/borgbackup/env/lib/python3.10/site-packages/borg/helpers/fs.py", line 290, in os_open
c5q0guvb@c5q0guvb.repo.borgbase.com:repo: Error running actions for repository
Command 'borg create --exclude-from /tmp/tmp9m68h84p --compression zstd --debug --show-rc --debug c5q0guvb@c5q0guvb.repo.borgbase.com:repo::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f} /volume2/homes/robert /volume2/nextcloud/jennifer/files /volume2/nextcloud/robert/files' returned non-zero exit status 2.
./borgmatic.yml: No commands to run for on-error hook
./borgmatic.yml: Error running configuration file
./borgmatic.yml: No commands to run for post-everything hook

summary:
./borgmatic.yml: Error running configuration file
c5q0guvb@c5q0guvb.repo.borgbase.com:repo: Error running actions for repository
...
Remote: Resolving repository path b'repo'
Remote: Resolved repository path to '/srv/repos/c5q0guvb/repo'
Remote: Verified integrity of /srv/repos/c5q0guvb/repo/index.4021
TAM-verified manifest
security: read previous location 'ssh://c5q0guvb@c5q0guvb.repo.borgbase.com/./repo'
security: read manifest timestamp '2022-06-02T13:47:38.881875'
security: determined newest manifest timestamp as 2022-06-02T13:47:38.881875
security: repository checks ok, allowing access
Creating archive at "c5q0guvb@c5q0guvb.repo.borgbase.com:repo::diskstation-2022-06-02T08:47:49.260208"
Verified integrity of /volume2/BorgBackup/.borg/.cache/borg/2d931852622812096ee5dec8e4e6b12b2d272e4f3c1f9e7ec694380368686f30/chunks
Reading files cache ...
Verified integrity of /volume2/BorgBackup/.borg/.cache/borg/2d931852622812096ee5dec8e4e6b12b2d272e4f3c1f9e7ec694380368686f30/files
security: read previous location 'ssh://c5q0guvb@c5q0guvb.repo.borgbase.com/./repo'
security: read manifest timestamp '2022-06-02T13:47:38.881875'
security: determined newest manifest timestamp as 2022-06-02T13:47:38.881875
security: repository checks ok, allowing access
Processing files ...
Remote: Cleaned up 0 uncommitted segment files (== everything after segment 4021).
Remote: Verified integrity of /srv/repos/c5q0guvb/repo/hints.4021
Remote: Storage quota: 867.44 GB out of 3.95 TB used.
/volume2/homes/robert/LogCenter/SYNOSYSLOGDB__ARCH.DB-shm: file changed while we backed it up
RemoteRepository: 192.51 MB bytes sent, 7.07 kB bytes received, 292 messages sent
Local Exception
Traceback (most recent call last):
  File "/volume2/@appstore/borgbackup/env/lib/python3.10/site-packages/borg/helpers/fs.py", line 290, in os_open
Command 'borg create --exclude-from /tmp/tmp9m68h84p --compression zstd --debug --show-rc --debug c5q0guvb@c5q0guvb.repo.borgbase.com:repo::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f} /volume2/homes/robert /volume2/nextcloud/jennifer/files /volume2/nextcloud/robert/files' returned non-zero exit status 2.

[ThomasWaldmann]

Traceback (most recent call last):
  File "/volume2/@appstore/borgbackup/env/lib/python3.10/site-packages/borg/helpers/fs.py", line 290, in os_open

That's not the complete traceback from borg. This needs to get fixed first to get more information.