Local exception, borg create returned non-zero exit status 2. #465

Closed
opened 2021-11-16 00:54:51 +00:00 by RocketSEA · 3 comments

What I'm trying to do and why

Complete the initial backup through a docker container (running on Unraid). The previous backup failed midway through for the same error code.

Command I'm trying to run:

borgmatic create --verbosity 2 --files --stats --log-file /var/log/borgmatic.log --log-file-verbosity 2

Steps to reproduce (if a bug)

Include (sanitized) borgmatic configuration files if applicable.

Config file:

location:
    source_directories:
        - /boot
        - /mnt/user/appdata
        - /mnt/user/ISOs
        - /mnt/user/Nextcloud
        - /mnt/user/misc
        - /mnt/user/paperless
        - /mnt/user/plex/movies
        - /mnt/user/VirtualMachinesCache
        - /mnt/user/WebBackups
    repositories:
        - /mnt/borg-repository
    one_file_system: true
    files_cache: mtime,size
    exclude_if_present:
        - .nobackup
        - .NOBACKUP

storage:
    encryption_passphrase: '***'
    compression: none
    ssh_command: ssh -i /root/.ssh/id_rsa
    archive_name_format: 'backup-{now}'
retention:
    keep_hourly: 1
    keep_daily: 1
    keep_weekly: 1
    keep_monthly: 1
    keep_yearly: 2
    prefix: 'backup-'

consistency:
    checks:
        - repository
        - archives
    prefix: 'backup-'

hooks:
    before_backup:
        - echo "Starting a backup."
    after_backup:
        - echo "Finished a backup."
    on_error:
        - echo "Error during prune/create/check."

Actual behavior (if a bug)

Include (sanitized) --verbosity 2 output if applicable.

Log file:

[2021-11-15 16:41:04,096] DEBUG: Ensuring legacy configuration is upgraded
[2021-11-15 16:41:04,097] DEBUG: /etc/borgmatic.d/config.yaml: No commands to run for pre-everything hook
[2021-11-15 16:41:04,097] INFO: /etc/borgmatic.d/config.yaml: Running command for pre-backup hook
[2021-11-15 16:41:04,097] DEBUG: echo "Starting a backup."
[2021-11-15 16:41:04,101] WARNING: Starting a backup.
[2021-11-15 16:41:04,102] INFO: /mnt/borg-repository: Creating archive
[2021-11-15 16:41:04,111] DEBUG: borg create --exclude-if-present .nobackup --exclude-if-present .NOBACKUP --compression none --one-file-system --files-cache mtime,size --list --filter AME- --stats --debug --show-rc /mnt/borg-repository::backup-{now} /boot /mnt/user/ISOs /mnt/user/Nextcloud /mnt/user/VirtualMachinesCache /mnt/user/WebBackups /mnt/user/appdata /mnt/user/misc /mnt/user/paperless /mnt/user/plex/movies
[2021-11-15 16:41:04,477] INFO: using builtin fallback logging configuration
[2021-11-15 16:41:04,823] INFO: 35 self tests completed in 0.35 seconds
[2021-11-15 16:41:04,829] INFO: Verified integrity of /mnt/borg-repository/index.97
[2021-11-15 16:41:04,947] INFO: TAM-verified manifest
[2021-11-15 16:41:04,953] INFO: security: read previous location '/mnt/borg-repository'
[2021-11-15 16:41:04,955] INFO: security: read manifest timestamp '2021-11-15T05:25:05.164774'
[2021-11-15 16:41:04,955] INFO: security: determined newest manifest timestamp as 2021-11-15T05:25:05.164774
[2021-11-15 16:41:04,957] INFO: security: repository checks ok, allowing access
[2021-11-15 16:41:04,957] INFO: Creating archive at "/mnt/borg-repository::backup-{now}"
[2021-11-15 16:41:04,962] INFO: Verified integrity of /root/.cache/borg/194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f/chunks
[2021-11-15 16:41:04,962] INFO: Reading files cache ...
[2021-11-15 16:41:04,963] INFO: security: read previous location '/mnt/borg-repository'
[2021-11-15 16:41:04,966] INFO: security: read manifest timestamp '2021-11-15T05:25:05.164774'
[2021-11-15 16:41:04,966] INFO: security: determined newest manifest timestamp as 2021-11-15T05:25:05.164774
[2021-11-15 16:41:04,966] INFO: security: repository checks ok, allowing access
[2021-11-15 16:41:04,968] INFO: Synchronizing chunks cache...
[2021-11-15 16:41:04,974] INFO: Archives: 1, w/ cached Idx: 0, w/ outdated Idx: 0, w/o cached Idx: 1.
[2021-11-15 16:41:04,975] INFO: Fetching and building archive index for backup-2021-11-14T20:55:03.checkpoint ...
[2021-11-15 16:41:05,066] INFO: Merging into master chunks index ...
[2021-11-15 16:41:05,069] INFO: Cache sync: had to fetch 0 B (0 chunks) because no archive had a csize set for them (due to --no-cache-sync)
[2021-11-15 16:41:05,070] INFO: Cache sync: processed 2.22 MB (17 chunks) of metadata
[2021-11-15 16:41:05,070] INFO: Cache sync: compact chunks.archive.d storage saved 470.27 kB bytes
[2021-11-15 16:41:05,070] INFO: Done.
[2021-11-15 16:41:05,071] INFO: security: saving state for 194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f to /root/.config/borg/security/194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f
[2021-11-15 16:41:05,090] INFO: security: current location   /mnt/borg-repository
[2021-11-15 16:41:05,090] INFO: security: key type           0
[2021-11-15 16:41:05,090] INFO: security: manifest timestamp 2021-11-15T05:25:05.164774
[2021-11-15 16:41:05,091] INFO: Local Exception
[2021-11-15 16:41:05,122] INFO: Traceback (most recent call last):
[2021-11-15 16:41:05,123] CRITICAL: /mnt/borg-repository: Error running actions for repository
[2021-11-15 16:41:05,123] CRITICAL: Command 'borg create --exclude-if-present .nobackup --exclude-if-present .NOBACKUP --compression none --one-file-system --files-cache mtime,size --list --filter AME- --stats --debug --show-rc /mnt/borg-repository::backup-{now} /boot /mnt/user/ISOs /mnt/user/Nextcloud /mnt/user/VirtualMachinesCache /mnt/user/WebBackups /mnt/user/appdata /mnt/user/misc /mnt/user/paperless /mnt/user/plex/movies' returned non-zero exit status 2.
[2021-11-15 16:41:05,124] INFO: /etc/borgmatic.d/config.yaml: Running command for on-error hook
[2021-11-15 16:41:05,124] DEBUG: echo "Error during prune/create/check."
[2021-11-15 16:41:05,128] ERROR: Error during prune/create/check.
[2021-11-15 16:41:05,129] CRITICAL: /etc/borgmatic.d/config.yaml: Error running configuration file
[2021-11-15 16:41:05,129] DEBUG: /etc/borgmatic.d/config.yaml: No commands to run for post-everything hook
[2021-11-15 16:41:05,129] CRITICAL: 
[2021-11-15 16:41:05,129] CRITICAL: summary:
[2021-11-15 16:41:05,129] CRITICAL: /etc/borgmatic.d/config.yaml: Error running configuration file
[2021-11-15 16:41:05,123] CRITICAL: /mnt/borg-repository: Error running actions for repository
[2021-11-15 16:41:05,123] CRITICAL: ...
security: read previous location '/mnt/borg-repository'
security: read manifest timestamp '2021-11-15T05:25:05.164774'
security: determined newest manifest timestamp as 2021-11-15T05:25:05.164774
security: repository checks ok, allowing access
Creating archive at "/mnt/borg-repository::backup-{now}"
Verified integrity of /root/.cache/borg/194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f/chunks
Reading files cache ...
security: read previous location '/mnt/borg-repository'
security: read manifest timestamp '2021-11-15T05:25:05.164774'
security: determined newest manifest timestamp as 2021-11-15T05:25:05.164774
security: repository checks ok, allowing access
Synchronizing chunks cache...
Archives: 1, w/ cached Idx: 0, w/ outdated Idx: 0, w/o cached Idx: 1.
Fetching and building archive index for backup-2021-11-14T20:55:03.checkpoint ...
Merging into master chunks index ...
Cache sync: had to fetch 0 B (0 chunks) because no archive had a csize set for them (due to --no-cache-sync)
Cache sync: processed 2.22 MB (17 chunks) of metadata
Cache sync: compact chunks.archive.d storage saved 470.27 kB bytes
Done.
security: saving state for 194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f to /root/.config/borg/security/194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f
security: current location   /mnt/borg-repository
security: key type           0
security: manifest timestamp 2021-11-15T05:25:05.164774
Local Exception
Traceback (most recent call last):
[2021-11-15 16:41:05,123] CRITICAL: Command 'borg create --exclude-if-present .nobackup --exclude-if-present .NOBACKUP --compression none --one-file-system --files-cache mtime,size --list --filter AME- --stats --debug --show-rc /mnt/borg-repository::backup-{now} /boot /mnt/user/ISOs /mnt/user/Nextcloud /mnt/user/VirtualMachinesCache /mnt/user/WebBackups /mnt/user/appdata /mnt/user/misc /mnt/user/paperless /mnt/user/plex/movies' returned non-zero exit status 2.
[2021-11-15 16:41:05,130] CRITICAL: 
[2021-11-15 16:41:05,130] CRITICAL: Need some help? https://torsion.org/borgmatic/#issues

Expected behavior (if a bug)

Backup completes successfully.

Other notes / implementation ideas

Environment

borgmatic version: 1.5.18

Use sudo borgmatic --version or sudo pip show borgmatic | grep ^Version

borgmatic installation method: Docker container

Borg version: 1.1.17

Use sudo borg --version

Python version: 3.8.10

Use python3 --version

Database version (if applicable): psql (PostgreSQL) 13.4

Use psql --version or mysql --version on client and server.

operating system and version: Unraid 6.9.2, Docker version 20.10.5

#### What I'm trying to do and why Complete the initial backup through a docker container (running on Unraid). The previous backup failed midway through for the same error code. Command I'm trying to run: ``` borgmatic create --verbosity 2 --files --stats --log-file /var/log/borgmatic.log --log-file-verbosity 2 ``` #### Steps to reproduce (if a bug) Include (sanitized) borgmatic configuration files if applicable. Config file: ``` location: source_directories: - /boot - /mnt/user/appdata - /mnt/user/ISOs - /mnt/user/Nextcloud - /mnt/user/misc - /mnt/user/paperless - /mnt/user/plex/movies - /mnt/user/VirtualMachinesCache - /mnt/user/WebBackups repositories: - /mnt/borg-repository one_file_system: true files_cache: mtime,size exclude_if_present: - .nobackup - .NOBACKUP storage: encryption_passphrase: '***' compression: none ssh_command: ssh -i /root/.ssh/id_rsa archive_name_format: 'backup-{now}' retention: keep_hourly: 1 keep_daily: 1 keep_weekly: 1 keep_monthly: 1 keep_yearly: 2 prefix: 'backup-' consistency: checks: - repository - archives prefix: 'backup-' hooks: before_backup: - echo "Starting a backup." after_backup: - echo "Finished a backup." on_error: - echo "Error during prune/create/check." ``` #### Actual behavior (if a bug) Include (sanitized) `--verbosity 2` output if applicable. Log file: ``` [2021-11-15 16:41:04,096] DEBUG: Ensuring legacy configuration is upgraded [2021-11-15 16:41:04,097] DEBUG: /etc/borgmatic.d/config.yaml: No commands to run for pre-everything hook [2021-11-15 16:41:04,097] INFO: /etc/borgmatic.d/config.yaml: Running command for pre-backup hook [2021-11-15 16:41:04,097] DEBUG: echo "Starting a backup." [2021-11-15 16:41:04,101] WARNING: Starting a backup. [2021-11-15 16:41:04,102] INFO: /mnt/borg-repository: Creating archive [2021-11-15 16:41:04,111] DEBUG: borg create --exclude-if-present .nobackup --exclude-if-present .NOBACKUP --compression none --one-file-system --files-cache mtime,size --list --filter AME- --stats --debug --show-rc /mnt/borg-repository::backup-{now} /boot /mnt/user/ISOs /mnt/user/Nextcloud /mnt/user/VirtualMachinesCache /mnt/user/WebBackups /mnt/user/appdata /mnt/user/misc /mnt/user/paperless /mnt/user/plex/movies [2021-11-15 16:41:04,477] INFO: using builtin fallback logging configuration [2021-11-15 16:41:04,823] INFO: 35 self tests completed in 0.35 seconds [2021-11-15 16:41:04,829] INFO: Verified integrity of /mnt/borg-repository/index.97 [2021-11-15 16:41:04,947] INFO: TAM-verified manifest [2021-11-15 16:41:04,953] INFO: security: read previous location '/mnt/borg-repository' [2021-11-15 16:41:04,955] INFO: security: read manifest timestamp '2021-11-15T05:25:05.164774' [2021-11-15 16:41:04,955] INFO: security: determined newest manifest timestamp as 2021-11-15T05:25:05.164774 [2021-11-15 16:41:04,957] INFO: security: repository checks ok, allowing access [2021-11-15 16:41:04,957] INFO: Creating archive at "/mnt/borg-repository::backup-{now}" [2021-11-15 16:41:04,962] INFO: Verified integrity of /root/.cache/borg/194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f/chunks [2021-11-15 16:41:04,962] INFO: Reading files cache ... [2021-11-15 16:41:04,963] INFO: security: read previous location '/mnt/borg-repository' [2021-11-15 16:41:04,966] INFO: security: read manifest timestamp '2021-11-15T05:25:05.164774' [2021-11-15 16:41:04,966] INFO: security: determined newest manifest timestamp as 2021-11-15T05:25:05.164774 [2021-11-15 16:41:04,966] INFO: security: repository checks ok, allowing access [2021-11-15 16:41:04,968] INFO: Synchronizing chunks cache... [2021-11-15 16:41:04,974] INFO: Archives: 1, w/ cached Idx: 0, w/ outdated Idx: 0, w/o cached Idx: 1. [2021-11-15 16:41:04,975] INFO: Fetching and building archive index for backup-2021-11-14T20:55:03.checkpoint ... [2021-11-15 16:41:05,066] INFO: Merging into master chunks index ... [2021-11-15 16:41:05,069] INFO: Cache sync: had to fetch 0 B (0 chunks) because no archive had a csize set for them (due to --no-cache-sync) [2021-11-15 16:41:05,070] INFO: Cache sync: processed 2.22 MB (17 chunks) of metadata [2021-11-15 16:41:05,070] INFO: Cache sync: compact chunks.archive.d storage saved 470.27 kB bytes [2021-11-15 16:41:05,070] INFO: Done. [2021-11-15 16:41:05,071] INFO: security: saving state for 194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f to /root/.config/borg/security/194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f [2021-11-15 16:41:05,090] INFO: security: current location /mnt/borg-repository [2021-11-15 16:41:05,090] INFO: security: key type 0 [2021-11-15 16:41:05,090] INFO: security: manifest timestamp 2021-11-15T05:25:05.164774 [2021-11-15 16:41:05,091] INFO: Local Exception [2021-11-15 16:41:05,122] INFO: Traceback (most recent call last): [2021-11-15 16:41:05,123] CRITICAL: /mnt/borg-repository: Error running actions for repository [2021-11-15 16:41:05,123] CRITICAL: Command 'borg create --exclude-if-present .nobackup --exclude-if-present .NOBACKUP --compression none --one-file-system --files-cache mtime,size --list --filter AME- --stats --debug --show-rc /mnt/borg-repository::backup-{now} /boot /mnt/user/ISOs /mnt/user/Nextcloud /mnt/user/VirtualMachinesCache /mnt/user/WebBackups /mnt/user/appdata /mnt/user/misc /mnt/user/paperless /mnt/user/plex/movies' returned non-zero exit status 2. [2021-11-15 16:41:05,124] INFO: /etc/borgmatic.d/config.yaml: Running command for on-error hook [2021-11-15 16:41:05,124] DEBUG: echo "Error during prune/create/check." [2021-11-15 16:41:05,128] ERROR: Error during prune/create/check. [2021-11-15 16:41:05,129] CRITICAL: /etc/borgmatic.d/config.yaml: Error running configuration file [2021-11-15 16:41:05,129] DEBUG: /etc/borgmatic.d/config.yaml: No commands to run for post-everything hook [2021-11-15 16:41:05,129] CRITICAL: [2021-11-15 16:41:05,129] CRITICAL: summary: [2021-11-15 16:41:05,129] CRITICAL: /etc/borgmatic.d/config.yaml: Error running configuration file [2021-11-15 16:41:05,123] CRITICAL: /mnt/borg-repository: Error running actions for repository [2021-11-15 16:41:05,123] CRITICAL: ... security: read previous location '/mnt/borg-repository' security: read manifest timestamp '2021-11-15T05:25:05.164774' security: determined newest manifest timestamp as 2021-11-15T05:25:05.164774 security: repository checks ok, allowing access Creating archive at "/mnt/borg-repository::backup-{now}" Verified integrity of /root/.cache/borg/194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f/chunks Reading files cache ... security: read previous location '/mnt/borg-repository' security: read manifest timestamp '2021-11-15T05:25:05.164774' security: determined newest manifest timestamp as 2021-11-15T05:25:05.164774 security: repository checks ok, allowing access Synchronizing chunks cache... Archives: 1, w/ cached Idx: 0, w/ outdated Idx: 0, w/o cached Idx: 1. Fetching and building archive index for backup-2021-11-14T20:55:03.checkpoint ... Merging into master chunks index ... Cache sync: had to fetch 0 B (0 chunks) because no archive had a csize set for them (due to --no-cache-sync) Cache sync: processed 2.22 MB (17 chunks) of metadata Cache sync: compact chunks.archive.d storage saved 470.27 kB bytes Done. security: saving state for 194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f to /root/.config/borg/security/194c739138a9e4ab5c7247e1cdbc23d7caa1ab449cb85a40662723708e82db4f security: current location /mnt/borg-repository security: key type 0 security: manifest timestamp 2021-11-15T05:25:05.164774 Local Exception Traceback (most recent call last): [2021-11-15 16:41:05,123] CRITICAL: Command 'borg create --exclude-if-present .nobackup --exclude-if-present .NOBACKUP --compression none --one-file-system --files-cache mtime,size --list --filter AME- --stats --debug --show-rc /mnt/borg-repository::backup-{now} /boot /mnt/user/ISOs /mnt/user/Nextcloud /mnt/user/VirtualMachinesCache /mnt/user/WebBackups /mnt/user/appdata /mnt/user/misc /mnt/user/paperless /mnt/user/plex/movies' returned non-zero exit status 2. [2021-11-15 16:41:05,130] CRITICAL: [2021-11-15 16:41:05,130] CRITICAL: Need some help? https://torsion.org/borgmatic/#issues ``` #### Expected behavior (if a bug) Backup completes successfully. #### Other notes / implementation ideas #### Environment **borgmatic version:** 1.5.18 Use `sudo borgmatic --version` or `sudo pip show borgmatic | grep ^Version` **borgmatic installation method:** Docker container **Borg version:** 1.1.17 Use `sudo borg --version` **Python version:** 3.8.10 Use `python3 --version` **Database version (if applicable):** psql (PostgreSQL) 13.4 Use `psql --version` or `mysql --version` on client and server. **operating system and version:** Unraid 6.9.2, Docker version 20.10.5
RocketSEA changed title from Local exception, borg create returned non-zero exist status 2. to Local exception, borg create returned non-zero exit status 2. 2021-11-16 00:58:19 +00:00
Owner

Thanks for the detailed issue write-up! What's weird in the log is that Borg is definitely erroring (exit code 2), and I see that there's a traceback, but I can't find the details of the traceback anywhere in the log. So here's my recommendation: Run Borg directly and see if you get any more useful output—like the actual contents of the Borg traceback. Conveniently, your borgmatic log contains the full Borg command it's running (minus any environment variables for things like encryption passphrases), so you should hopefully be able to reproduce the problem pretty easily.

Let me know what you find!

Thanks for the detailed issue write-up! What's weird in the log is that Borg is definitely erroring (exit code 2), and I see that there's a traceback, but I can't find the details of the traceback anywhere in the log. So here's my recommendation: Run Borg directly and see if you get any more useful output—like the actual contents of the Borg traceback. Conveniently, your borgmatic log contains the full Borg command it's running (minus any environment variables for things like encryption passphrases), so you should *hopefully* be able to reproduce the problem pretty easily. Let me know what you find!
Author

Thanks, don't know why I didn't think to run that. Here's the actual error if you were curious:

OSError: [Errno 28] No space left on device

However, this is odd because Unraid shows 12.7 TB free, as does a df -h:

/dev/sdm1                12.7T    136.0G     12.6T   1% /mnt/borg-repository

I suppose it isn't an issue with Borgmatic, though!

Thanks, don't know why I didn't think to run that. Here's the actual error if you were curious: ``` OSError: [Errno 28] No space left on device ``` However, this is odd because Unraid shows 12.7 TB free, as does a df -h: ``` /dev/sdm1 12.7T 136.0G 12.6T 1% /mnt/borg-repository ``` I suppose it isn't an issue with Borgmatic, though!
Author

Bingo! Here's my issue:

tmpfs                     1.0M   1020.0K      4.0K 100% /root/.cache/borg

Ref:
https://github.com/borgbackup/borg/issues/3994

Closing for now!

Bingo! Here's my issue: ``` tmpfs 1.0M 1020.0K 4.0K 100% /root/.cache/borg ``` Ref: https://github.com/borgbackup/borg/issues/3994 Closing for now!
Sign in to join this conversation.
No Milestone
No Assignees
2 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: borgmatic-collective/borgmatic#465
No description provided.