Cannot determine Borg repository ID #598
No Assignees
Notifications
Due Date
No due date set.
Dependencies
No dependencies set.
Reference: borgmatic-collective/borgmatic#598
Loading…
x
Reference in New Issue
Block a user
No description provided.
Delete Branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
What I'm trying to do and why
All eight of my borgmatic backups broke with the most recent update.
In each instance the error reads like this:
[2022-10-14 09:38:29,067] CRITICAL: /mnt/data/backup: Error running actions for repository
[2022-10-14 09:38:29,068] CRITICAL: Cannot determine Borg repository ID for /mnt/data/backup
The log with verbosity 2 shows the error occurs immediately after:
[2022-10-14 09:38:27,666] DEBUG: borg info --json /mnt/data/backup
Running
borg info --json /mnt/data/backupdirectly from the command line yields correct results.I reproduce my configuration files and debug log below. Thanks for your help.
Steps to reproduce (if a bug)
location:
source_directories:
- /home/joseph
repositories:
- /mnt/data/backup
exclude_from:
- /home/joseph/.config/borgmatic.d/common/borg_excludes
exclude_caches: true
storage:
compression: lz4
encryption_passcommand: [sanitized]
archive_name_format: '{hostname}-{now:%Y-%m-%d@%H:%M}'
retention:
!include /home/joseph/.config/borgmatic.d/common/common_retention.yaml
consistency:
checks:
- repository
- archives
hooks:
before_backup:
- findmnt /mnt/data > /dev/null || exit 75
healthchecks: [sanitized]
Actual behavior (if a bug)
[2022-10-14 09:36:45,425] DEBUG: Ensuring legacy configuration is upgraded
[2022-10-14 09:36:45,425] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for pre-everything hook
[2022-10-14 09:36:45,425] DEBUG: borg --version --debug --show-rc
[2022-10-14 09:36:45,563] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Calling healthchecks hook function initialize_monitor
[2022-10-14 09:36:45,563] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Calling healthchecks hook function ping_monitor
[2022-10-14 09:36:45,563] INFO: /home/joseph/.config/borgmatic.d/borg.data.yaml: Pinging Healthchecks start
[2022-10-14 09:36:45,563] Sanitized
[2022-10-14 09:36:46,499] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for pre-actions hook
[2022-10-14 09:36:46,500] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for pre-prune hook
[2022-10-14 09:36:46,500] INFO: /mnt/data/backup: Pruning archives
[2022-10-14 09:36:46,500] DEBUG: borg prune --keep-daily 7 --keep-weekly 4 --keep-monthly 6 --keep-yearly 5 --glob-archives {hostname}* --debug --show-rc /mnt/data/backup
[2022-10-14 09:36:46,636] INFO: using builtin fallback logging configuration
[2022-10-14 09:36:46,684] INFO: 33 self tests completed in 0.05 seconds
[2022-10-14 09:36:46,736] INFO: Verified integrity of /mnt/data/backup/index.5303
[2022-10-14 09:36:46,810] INFO: gpg: Sanitized
[2022-10-14 09:36:46,862] INFO: TAM-verified manifest
[2022-10-14 09:36:46,863] INFO: security: read previous location '/mnt/data/backup'
[2022-10-14 09:36:46,863] INFO: security: read manifest timestamp '2022-10-14T13:26:12.450380'
[2022-10-14 09:36:46,863] INFO: security: determined newest manifest timestamp as 2022-10-14T13:26:12.450380
[2022-10-14 09:36:46,871] INFO: security: repository checks ok, allowing access
[2022-10-14 09:36:46,937] INFO: Verified integrity of /home/joseph/.cache/borg/885afbb056aac57a9324a5da7e519a28dd987cf6cfe0284b9d4858b4ee257f0d/chunks
[2022-10-14 09:36:46,937] INFO: security: read previous location '/mnt/data/backup'
[2022-10-14 09:36:46,937] INFO: security: read manifest timestamp '2022-10-14T13:26:12.450380'
[2022-10-14 09:36:46,937] INFO: security: determined newest manifest timestamp as 2022-10-14T13:26:12.450380
[2022-10-14 09:36:46,937] INFO: security: repository checks ok, allowing access
[2022-10-14 09:36:47,075] INFO: Cleaned up 0 uncommitted segment files (== everything after segment 5303).
[2022-10-14 09:36:47,076] INFO: Verified integrity of /mnt/data/backup/hints.5303
[2022-10-14 09:36:54,323] INFO: check_free_space: required bytes 1035713008, free bytes 441418645504
[2022-10-14 09:36:55,531] INFO: security: saving state for 885afbb056aac57a9324a5da7e519a28dd987cf6cfe0284b9d4858b4ee257f0d to /home/joseph/.config/borg/security/885afbb056aac57a9324a5da7e519a28dd987cf6cfe0284b9d4858b4ee257f0d
[2022-10-14 09:36:55,531] INFO: security: current location /mnt/data/backup
[2022-10-14 09:36:55,531] INFO: security: key type 3
[2022-10-14 09:36:55,531] INFO: security: manifest timestamp 2022-10-14T13:36:54.153600
[2022-10-14 09:36:55,900] INFO: terminating with success status, rc 0
[2022-10-14 09:36:55,918] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for post-prune hook
[2022-10-14 09:36:55,918] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for pre-compact hook
[2022-10-14 09:36:55,918] INFO: /mnt/data/backup: Compacting segments
[2022-10-14 09:36:55,918] DEBUG: borg compact --debug --show-rc /mnt/data/backup
[2022-10-14 09:36:56,049] INFO: using builtin fallback logging configuration
[2022-10-14 09:36:56,097] INFO: 33 self tests completed in 0.05 seconds
[2022-10-14 09:36:56,143] INFO: Verified integrity of /mnt/data/backup/index.5307
[2022-10-14 09:36:56,144] INFO: Cleaned up 0 uncommitted segment files (== everything after segment 5307).
[2022-10-14 09:36:56,145] INFO: Verified integrity of /mnt/data/backup/hints.5307
[2022-10-14 09:36:56,199] INFO: check_free_space: required bytes 1035713068, free bytes 441418616832
[2022-10-14 09:36:56,283] INFO: Compaction started (threshold is 10%).
[2022-10-14 09:36:56,283] INFO: not compacting segment 201 (maybe freeable: 0.01% [69591 bytes])
[2022-10-14 09:36:56,283] INFO: not compacting segment 205 (maybe freeable: 0.18% [201862 bytes])
-SNIP. Trimmed ~100 similar entries-
[2022-10-14 09:36:57,693] INFO: compacting segment 5304 with usage count 0 (maybe freeable: 99.84% [5084 bytes])
[2022-10-14 09:36:57,695] INFO: dropping DEL for id 3885bd8bf985941751b62fdf6d20af0dc5b4ad699c303db63298f99b6cb94db5 - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id 9576b0032b5cc05060cd625e04b9500066619090d28d2bf08cfe8b1128b50a25 - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id cad19b0be7bd46c2e4951074e12d276f6b93572a204634798191c311026ff488 - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id 350df420d16dc130fb344d39faab536ca755750873513276ba0c81c23f814849 - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id 4a0c843b39b8471e9f3848cdc82b71102d936247f9ba71dc565390a905613d05 - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id 0517ea8f9307bede16e65974c7383e8f50bc4a7fe72cbe2dc78c57264f191da9 - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id a2000f65662071e4ed6c6ff27e33e1685f20c60039e3c1dedd503c4cafd61ebf - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id f367a4b65678aabe0f6d2d75f4f574d8946853ace19f36b6f5b0df19030a4a48 - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id c0efc59d25e3127dcfd464542dd677c57591b5f8a25415efbb037eade33e619b - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id d7daf9ab67290ffe8db141cc962c0f328fa516d649dca609d5d664310a78d44c - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id 5f6c5e5f520fea8ccf828d2915de728cf38e91bc65f932fdf3d396ce3574fbcf - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id 9958e895e2e816e9e8e3d6b64026ed687e2e0c796c3dded57bb2ebe93e60a94f - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id 31ac628a536728fe1cc931a8da943f83c7e6eed213f28e4d5320d013895b5b42 - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: dropping DEL for id 28378f69f742a2202bcd5571b173f50647d861b0dbfc18625599cd6b5b9b51fc - seg 5304, iti 5307, knisi False, spe False, dins False, si []
[2022-10-14 09:36:57,695] INFO: compacting segment 5305 with usage count 0 (maybe freeable: 83.67% [41 bytes])
[2022-10-14 09:36:57,696] INFO: compacting segment 5306 with usage count 0 (maybe freeable: 99.88% [6591 bytes])
[2022-10-14 09:36:57,696] INFO: compacting segment 5307 with usage count 0 (maybe freeable: 52.94% [9 bytes])
[2022-10-14 09:36:57,696] INFO: compacting segment 5308 with usage count 0 (maybe freeable: 83.67% [41 bytes])
[2022-10-14 09:36:57,696] INFO: compacting segment 5310 with usage count 0 (maybe freeable: 52.94% [9 bytes])
[2022-10-14 09:36:59,023] INFO: complete_xfer: wrote commit at segment 5312
[2022-10-14 09:36:59,023] INFO: complete_xfer: deleting unused segment 5287
[2022-10-14 09:36:59,071] INFO: complete_xfer: deleting unused segment 5296
[2022-10-14 09:36:59,072] INFO: complete_xfer: deleting unused segment 5299
[2022-10-14 09:36:59,072] INFO: complete_xfer: deleting unused segment 5301
[2022-10-14 09:36:59,073] INFO: complete_xfer: deleting unused segment 5302
[2022-10-14 09:36:59,073] INFO: complete_xfer: deleting unused segment 5303
[2022-10-14 09:36:59,073] INFO: complete_xfer: deleting unused segment 5304
[2022-10-14 09:36:59,074] INFO: complete_xfer: deleting unused segment 5305
[2022-10-14 09:36:59,074] INFO: complete_xfer: deleting unused segment 5306
[2022-10-14 09:36:59,074] INFO: complete_xfer: deleting unused segment 5307
[2022-10-14 09:36:59,075] INFO: complete_xfer: deleting unused segment 5308
[2022-10-14 09:36:59,075] INFO: complete_xfer: deleting unused segment 5310
[2022-10-14 09:36:59,075] INFO: compaction freed about 40.08 MB repository space.
[2022-10-14 09:36:59,076] INFO: compaction completed.
[2022-10-14 09:37:00,213] INFO: terminating with success status, rc 0
[2022-10-14 09:37:00,234] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for post-compact hook
[2022-10-14 09:37:00,234] INFO: /home/joseph/.config/borgmatic.d/borg.data.yaml: Running command for pre-backup hook
[2022-10-14 09:37:00,234] DEBUG: findmnt /mnt/data > /dev/null || exit 75
[2022-10-14 09:37:00,239] INFO: /mnt/data/backup: Creating archive
[2022-10-14 09:37:00,239] DEBUG: /mnt/data/backup: Calling postgresql_databases hook function remove_database_dumps
[2022-10-14 09:37:00,239] DEBUG: /mnt/data/backup: Removing PostgreSQL database dumps
[2022-10-14 09:37:00,239] DEBUG: /mnt/data/backup: Calling mysql_databases hook function remove_database_dumps
[2022-10-14 09:37:00,239] DEBUG: /mnt/data/backup: Removing MySQL database dumps
[2022-10-14 09:37:00,239] DEBUG: /mnt/data/backup: Calling mongodb_databases hook function remove_database_dumps
[2022-10-14 09:37:00,239] DEBUG: /mnt/data/backup: Removing MongoDB database dumps
[2022-10-14 09:37:00,240] DEBUG: borg create --exclude-from /home/joseph/.config/borgmatic.d/common/borg_excludes --exclude-caches --compression lz4 /mnt/data/backup::{hostname}-{now:%Y-%m-%d@%H:%M} /home/joseph --debug --show-rc
[2022-10-14 09:37:00,368] INFO: using builtin fallback logging configuration
[2022-10-14 09:37:00,414] INFO: 33 self tests completed in 0.05 seconds
[2022-10-14 09:37:00,459] INFO: Verified integrity of /mnt/data/backup/index.5312
[2022-10-14 09:37:00,557] INFO: gpg: Sanitized
[2022-10-14 09:37:00,609] INFO: TAM-verified manifest
[2022-10-14 09:37:00,618] INFO: security: read previous location '/mnt/data/backup'
[2022-10-14 09:37:00,618] INFO: security: read manifest timestamp '2022-10-14T13:36:54.153600'
[2022-10-14 09:37:00,618] INFO: security: determined newest manifest timestamp as 2022-10-14T13:36:54.153600
[2022-10-14 09:37:00,618] INFO: security: repository checks ok, allowing access
[2022-10-14 09:37:00,618] INFO: Creating archive at "/mnt/data/backup::arch-2022-10-14@09:37"
[2022-10-14 09:37:00,668] INFO: Verified integrity of /home/joseph/.cache/borg/885afbb056aac57a9324a5da7e519a28dd987cf6cfe0284b9d4858b4ee257f0d/chunks
[2022-10-14 09:37:00,668] INFO: Reading files cache ...
[2022-10-14 09:37:02,319] INFO: Verified integrity of /home/joseph/.cache/borg/885afbb056aac57a9324a5da7e519a28dd987cf6cfe0284b9d4858b4ee257f0d/files
[2022-10-14 09:37:02,319] INFO: security: read previous location '/mnt/data/backup'
[2022-10-14 09:37:02,319] INFO: security: read manifest timestamp '2022-10-14T13:36:54.153600'
[2022-10-14 09:37:02,319] INFO: security: determined newest manifest timestamp as 2022-10-14T13:36:54.153600
[2022-10-14 09:37:02,319] INFO: security: repository checks ok, allowing access
[2022-10-14 09:37:02,319] INFO: Processing files ...
[2022-10-14 09:37:02,551] INFO: Cleaned up 0 uncommitted segment files (== everything after segment 5312).
[2022-10-14 09:37:02,553] INFO: Verified integrity of /mnt/data/backup/hints.5312
[2022-10-14 09:38:23,950] INFO: check_free_space: required bytes 1035712938, free bytes 441308618752
[2022-10-14 09:38:25,118] INFO: security: saving state for 885afbb056aac57a9324a5da7e519a28dd987cf6cfe0284b9d4858b4ee257f0d to /home/joseph/.config/borg/security/885afbb056aac57a9324a5da7e519a28dd987cf6cfe0284b9d4858b4ee257f0d
[2022-10-14 09:38:25,118] INFO: security: current location /mnt/data/backup
[2022-10-14 09:38:25,118] INFO: security: key type 3
[2022-10-14 09:38:25,118] INFO: security: manifest timestamp 2022-10-14T13:38:23.815366
[2022-10-14 09:38:27,644] INFO: terminating with success status, rc 0
[2022-10-14 09:38:27,666] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Calling postgresql_databases hook function remove_database_dumps
[2022-10-14 09:38:27,666] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Removing PostgreSQL database dumps
[2022-10-14 09:38:27,666] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Calling mysql_databases hook function remove_database_dumps
[2022-10-14 09:38:27,666] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Removing MySQL database dumps
[2022-10-14 09:38:27,666] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Calling mongodb_databases hook function remove_database_dumps
[2022-10-14 09:38:27,666] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Removing MongoDB database dumps
[2022-10-14 09:38:27,666] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for post-backup hook
[2022-10-14 09:38:27,666] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for pre-check hook
[2022-10-14 09:38:27,666] INFO: /mnt/data/backup: Running consistency checks
[2022-10-14 09:38:27,666] DEBUG: borg info --json /mnt/data/backup
[2022-10-14 09:38:29,067] CRITICAL: /mnt/data/backup: Error running actions for repository
[2022-10-14 09:38:29,068] CRITICAL: Cannot determine Borg repository ID for /mnt/data/backup
[2022-10-14 09:38:29,068] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for on-error hook
[2022-10-14 09:38:29,068] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Calling healthchecks hook function ping_monitor
[2022-10-14 09:38:29,068] INFO: /home/joseph/.config/borgmatic.d/borg.data.yaml: Pinging Healthchecks fail
[2022-10-14 09:38:29,068] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Using Healthchecks ping URL https://hc-ping.com/2f0fb661-bfd8-4f3d-a623-1c6833e34810/fail
[2022-10-14 09:38:29,957] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: Calling healthchecks hook function destroy_monitor
[2022-10-14 09:38:29,958] CRITICAL: /home/joseph/.config/borgmatic.d/borg.data.yaml: Error running configuration file
[2022-10-14 09:38:29,958] DEBUG: /home/joseph/.config/borgmatic.d/borg.data.yaml: No commands to run for post-everything hook
[2022-10-14 09:38:29,958] CRITICAL:
[2022-10-14 09:38:29,959] CRITICAL: summary:
[2022-10-14 09:38:29,958] CRITICAL: /home/joseph/.config/borgmatic.d/borg.data.yaml: Error running configuration file
[2022-10-14 09:38:29,067] CRITICAL: /mnt/data/backup: Error running actions for repository
[2022-10-14 09:38:29,068] CRITICAL: Cannot determine Borg repository ID for /mnt/data/backup
[2022-10-14 09:38:29,959] CRITICAL:
[2022-10-14 09:38:29,960] CRITICAL: Need some help? https://torsion.org/borgmatic/#issues
Expected behavior (if a bug)
These settings have run daily without error for over a year. It is only with yesterday's upgrade that this happened.
Other notes / implementation ideas
Environment
borgmatic version: 1.7.3
Use
sudo borgmatic --versionorsudo pip show borgmatic | grep ^Versionborgmatic installation method: [e.g., Debian package, Docker container, etc.]
Arch User Repository package
Borg version: 1.2.2
sud
sudo borg --versionPython version: 3.10.8
Use
python3 --versionDatabase version (if applicable): psql (PostgreSQL) 14.5
Use
psql --versionormysql --versionon client and server.operating system and version: Linux 6.0.1-arch2-1
Thanks for taking the time to report this! I think what's going on here is the same thing as #597 .. A "minor" change to command execution broke repository ID detection in certain cases.
Fix released in borgmatic 1.7.4. Please give it a shot and let me know if it works for you. Thanks!
It works again. Thanks very much for the prompt fix on this!