borgmatic-collective/borgmatic
borgmatic-collective/borgmatic
14
58
Fork 42
Code Issues 62 Pull Requests 2 Actions Packages Releases 122 Activity

Cannot determine Borg repository ID #598

New Issue
Closed
opened 2022-10-14 15:16:05 +00:00 by scalice · 3 comments
scalice commented 2022-10-14 15:16:05 +00:00
Copy Link

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/backup directly 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 --version or sudo pip show borgmatic | grep ^Version

borgmatic installation method: [e.g., Debian package, Docker container, etc.]

Arch User Repository package

Borg version: 1.2.2

sud sudo borg --version

Python version: 3.10.8

Use python3 --version

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

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

operating system and version: Linux 6.0.1-arch2-1

#### 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/backup` directly 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 --version` or `sudo pip show borgmatic | grep ^Version` **borgmatic installation method:** [e.g., Debian package, Docker container, etc.] Arch User Repository package **Borg version:** 1.2.2 sud `sudo borg --version` **Python version:** 3.10.8 Use `python3 --version` **Database version (if applicable):** psql (PostgreSQL) 14.5 Use `psql --version` or `mysql --version` on client and server. **operating system and version:** Linux 6.0.1-arch2-1
witten commented 2022-10-14 16:50:00 +00:00
Owner
Copy Link

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.

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.
witten added the
bug
 label 2022-10-14 16:50:08 +00:00
witten commented 2022-10-14 23:30:10 +00:00
Owner
Copy Link

Fix released in borgmatic 1.7.4. Please give it a shot and let me know if it works for you. Thanks!

Fix released in borgmatic 1.7.4. Please give it a shot and let me know if it works for you. Thanks!
scalice commented 2022-10-15 13:45:47 +00:00
Author
Copy Link

It works again. Thanks very much for the prompt fix on this!

It works again. Thanks very much for the prompt fix on this!
👍 1
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels   
bug

   
data loss

   
design finalized

   
good first issue

   
new feature area

   
question / support

   
security

   
waiting for response
No Label
bug
data loss
design finalized
good first issue
new feature area
question / support
security
waiting for response
Milestone
Clear milestone
No items
No Milestone
Assignees
Clear assignees
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#598
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?