borg borg compact makes my repo wrong

Have you checked borgbackup docs, FAQ, and open Github issues?

Yes

Is this a BUG / ISSUE report or a QUESTION?

BUG

System information. For client/server mode post info for both machines.

Your borg version (borg -V).

1.2.0

Operating system (distribution) and version.

Manjaro linux

Hardware / network configuration, and filesystems used.

How much data is handled by borg?

repo directory size is 77 Gb

Full borg commandline that lead to the problem (leave away excludes and passwords)

borg compact /backup/borg

Describe the problem you're observing.

I used borg since 2018 without any problems. It runs via cron and makes backups in every hours. There is an anacron job starting every day which runs borg prune and borg check on the repository. Borg check never found any problem before now. Today I started a borg compact command to save some disk space. After that I started borg check again and it found some index problems.

Can you reproduce the problem? If so, describe how. If not, describe troubleshooting steps you took before opening the issue.

Yes, I can. I copied back an earlier backup from an external drive. Borg check runs without errors on it. After borg compact, borg check find index errors again.

Include any warning/errors/backtraces from the system logs

Before borg compact

Starting repository check
finished segment check at segment 52929
Starting repository index check
Index object count match.
Finished full repository check, no problems found.
Starting archive consistency check...
Analyzing archive cornflower-2018-12-31_23:30 (1/99)
Analyzing archive cornflower-2019-04-30_18:30 (2/99)
Analyzing archive cornflower-2019-05-31_20:30 (3/99)
Analyzing archive cornflower-2019-06-30_22:30 (4/99)
Analyzing archive cornflower-2019-07-31_23:30 (5/99)
Analyzing archive cornflower-2019-08-31_11:30 (6/99)
Analyzing archive cornflower-2019-09-30_17:30 (7/99)
Analyzing archive cornflower-2019-10-31_21:30 (8/99)
Analyzing archive cornflower-2019-11-29_06:30 (9/99)
Analyzing archive cornflower-2019-12-31_22:30 (10/99)
Analyzing archive cornflower-2020-01-31_22:30 (11/99)
Analyzing archive cornflower-2020-02-29_19:30 (12/99)
Analyzing archive cornflower-2020-03-31_21:30 (13/99)
Analyzing archive cornflower-2020-04-30_22:30 (14/99)
Analyzing archive cornflower-2020-05-31_22:30 (15/99)
Analyzing archive cornflower-2020-06-30_21:30 (16/99)
Analyzing archive cornflower-2020-07-31_21:30 (17/99)
Analyzing archive cornflower-2020-08-31_22:30 (18/99)
Analyzing archive cornflower-2020-09-30_21:30 (19/99)
Analyzing archive cornflower-2020-10-31_21:30 (20/99)
Analyzing archive cornflower-2020-11-30_19:30 (21/99)
Analyzing archive cornflower-2020-12-31_22:30 (22/99)
Analyzing archive cornflower-2021-01-31_15:30 (23/99)
Analyzing archive cornflower-2021-02-28_12:30 (24/99)
Analyzing archive cornflower-2021-03-31_20:30 (25/99)
Analyzing archive cornflower-2021-04-30_23:30 (26/99)
Analyzing archive cornflower-2021-05-31_16:30 (27/99)
Analyzing archive cornflower-2021-06-30_22:30 (28/99)
Analyzing archive cornflower-2021-07-31_09:30 (29/99)
Analyzing archive cornflower-2021-08-31_21:30 (30/99)
Analyzing archive cornflower-2021-09-30_22:30 (31/99)
Analyzing archive cornflower-2021-10-31_19:30 (32/99)
Analyzing archive cornflower-2021-11-30_20:30 (33/99)
Analyzing archive cornflower-2021-12-31_13:30 (34/99)
Analyzing archive cornflower-2022-01-31_09:30 (35/99)
Analyzing archive cornflower-2022-02-20_19:30 (36/99)
Analyzing archive cornflower-2022-02-27_19:30 (37/99)
Analyzing archive cornflower-2022-02-28_14:30 (38/99)
Analyzing archive cornflower-2022-03-06_19:30 (39/99)
Analyzing archive cornflower-2022-03-13_19:30 (40/99)
Analyzing archive cornflower-2022-03-20_18:30 (41/99)
Analyzing archive cornflower-2022-03-27_19:30 (42/99)
Analyzing archive cornflower-2022-03-31_21:30 (43/99)
Analyzing archive cornflower-2022-04-03_15:30 (44/99)
Analyzing archive cornflower-2022-04-10_21:30 (45/99)
Analyzing archive cornflower-2022-04-17_21:30 (46/99)
Analyzing archive cornflower-2022-04-24_12:30 (47/99)
Analyzing archive cornflower-2022-04-30_20:30 (48/99)
Analyzing archive cornflower-2022-05-01_21:30 (49/99)
Analyzing archive cornflower-2022-05-08_20:30 (50/99)
Analyzing archive cornflower-2022-05-15_20:30 (51/99)
Analyzing archive cornflower-2022-05-22_21:30 (52/99)
Analyzing archive cornflower-2022-05-23_16:30 (53/99)
Analyzing archive cornflower-2022-05-24_22:30 (54/99)
Analyzing archive cornflower-2022-05-25_20:30 (55/99)
Analyzing archive cornflower-2022-05-26_19:30 (56/99)
Analyzing archive cornflower-2022-05-28_11:30 (57/99)
Analyzing archive cornflower-2022-05-29_19:30 (58/99)
Analyzing archive cornflower-2022-05-30_15:30 (59/99)
Analyzing archive cornflower-2022-05-31_16:30 (60/99)
Analyzing archive cornflower-2022-06-01_22:30 (61/99)
Analyzing archive cornflower-2022-06-02_20:30 (62/99)
Analyzing archive cornflower-2022-06-03_21:30 (63/99)
Analyzing archive cornflower-2022-06-04_22:30 (64/99)
Analyzing archive cornflower-2022-06-05_22:30 (65/99)
Analyzing archive cornflower-2022-06-06_20:30 (66/99)
Analyzing archive cornflower-2022-06-07_20:30 (67/99)
Analyzing archive cornflower-2022-06-08_16:30 (68/99)
Analyzing archive cornflower-2022-06-09_19:30 (69/99)
Analyzing archive cornflower-2022-06-10_21:30 (70/99)
Analyzing archive cornflower-2022-06-11_22:30 (71/99)
Analyzing archive cornflower-2022-06-12_21:30 (72/99)
Analyzing archive cornflower-2022-06-13_21:30 (73/99)
Analyzing archive cornflower-2022-06-14_13:30 (74/99)
Analyzing archive cornflower-2022-06-15_19:30 (75/99)
Analyzing archive cornflower-2022-06-15_20:30 (76/99)
Analyzing archive cornflower-2022-06-15_21:30 (77/99)
Analyzing archive cornflower-2022-06-16_04:30 (78/99)
Analyzing archive cornflower-2022-06-16_05:30 (79/99)
Analyzing archive cornflower-2022-06-16_06:30 (80/99)
Analyzing archive cornflower-2022-06-16_07:30 (81/99)
Analyzing archive cornflower-2022-06-16_18:30 (82/99)
Analyzing archive cornflower-2022-06-16_19:30 (83/99)
Analyzing archive cornflower-2022-06-17_10:30 (84/99)
Analyzing archive cornflower-2022-06-17_14:30 (85/99)
Analyzing archive cornflower-2022-06-17_15:30 (86/99)
Analyzing archive cornflower-2022-06-17_16:30 (87/99)
Analyzing archive cornflower-2022-06-17_17:30 (88/99)
Analyzing archive cornflower-2022-06-17_18:30 (89/99)
Analyzing archive cornflower-2022-06-17_19:30 (90/99)
Analyzing archive cornflower-2022-06-17_20:30 (91/99)
Analyzing archive cornflower-2022-06-17_21:30 (92/99)
Analyzing archive cornflower-2022-06-18_09:30 (93/99)
Analyzing archive cornflower-2022-06-18_17:30 (94/99)
Analyzing archive cornflower-2022-06-18_18:30 (95/99)
Analyzing archive cornflower-2022-06-18_19:30 (96/99)
Analyzing archive cornflower-2022-06-18_20:30 (97/99)
Analyzing archive cornflower-2022-06-18_21:30 (98/99)
Analyzing archive cornflower-2022-06-18_22:33 (99/99)
Archive consistency check complete, no problems found.

After "borg compact"

Starting repository check
finished segment check at segment 52963
Starting repository index check
Index object count mismatch.
committed index: 241584 objects
rebuilt index:   241588 objects
ID: e92b2f600f14ca4d5b2fbce63cdda0826e858b0d95481d1d0d2596c458413139 rebuilt index: (48506, 416273957) committed index: <not found>     
ID: 0c39186794cc1f7ff3c8231b43cb2e552a82d0fce56bd27f4abaa188a08a083b rebuilt index: (48506, 416274095) committed index: <not found>     
ID: f110aa3465f8f7988cf610b251bd81d4e3326b93f174ba88bc966897252930a7 rebuilt index: (47096, 269064924) committed index: <not found>     
ID: 3f350ca73a648a816e04c2cb1a294d2d0940ec7aca7bb49c78256c38fa7f0528 rebuilt index: (26597, 200438556) committed index: <not found>     
Finished full repository check, errors found.

Jun 20 '22 20:06 DSpammy

duplicate of #6687?

if you could run a full borg check (including the archives check), we could see if there is any serious issue.

Jun 20 '22 21:06 ThomasWaldmann

And please keep your copy of the original repo that causes this. It sounds like you are able to reproduce the issue, which will be helpful in debugging it. Maybe the compact command can be modified to print its actions, so we can figure out what it is doing wrong?

Jun 20 '22 23:06 jdchristensen

Sorry for my lateness, I was not at home a few days. Now I made run the whole process again and the result is below. It was very sloooow on my 10+ years old PC.

Demonstrate borg repo damage after borg compact command Demo script: #!/bin/bash

echo "Demonstrate borg repo damage after borg compact command" echo "Demo script:" cat $0

date +%T

export BORG_PASSCOMMAND='cat /root/work/borg-backup/pass'

echo "delete repo" rm -rf /backup/borg

echo "restore saved config and cache files" rm -fr /root/.cache/borg cp -r /home/zsa/work/media/borg-old-cc/.cache/borg /root/.cache rm -fr /root/.config/borg cp -r /home/zsa/work/media/borg-old-cc/.config/borg /root/.config

echo "restore saved repo" cp -a /home/zsa/work/media/borg-old /backup

echo "rename saved repo to borg" mv /backup/borg-old /backup/borg

echo "check repo before compact" borg check -v --repository-only /backup/borg date +%T

echo "check archives before compact" borg check -v --archives-only /backup/borg date +%T

echo "run borg compact" borg compact --cleanup-commits /backup/borg date +%T

echo "check repo after compact" borg check -v --repository-only /backup/borg date +%T

echo "check archives after compact" borg check -v --archives-only /backup/borg date +%T

echo "try to repair" borg check -v --repair /backup/borg date +%T

echo "check archives after repair" borg check -v --archives-only /backup/borg date +%T

echo "******************** end ********************" 07:47:30 delete repo restore saved config and cache files restore saved repo rename saved repo to borg check repo before compact Starting repository check finished segment check at segment 52929 Starting repository index check Index object count match. Finished full repository check, no problems found. 08:34:56 check archives before compact Starting archive consistency check... Analyzing archive cornflower-2018-12-31_23:30 Archive consistency check complete, no problems found. 09:19:06 try to repair This is a potentially dangerous function. check --repair might lead to data loss (for kinds of corruption it is not capable of dealing with). BE VERY CAREFUL!

Type 'YES' if you understand this and want to continue: Starting repository check finished segment check at segment 52963 Starting repository index check Finished full repository check, no problems found. Starting archive consistency check... Analyzing archive cornflower-2018-12-31_23:30 Archive consistency check complete, no problems found. 10:14:53 ******************** end ********************

Jun 26 '22 08:06 DSpammy

That makes it really look like there is a bug in borg compact. @DSpammy , can you say more about how the repo was used? Was it always accessed locally? Did more than one client access it? Did you have any disk errors or other errors in the past? Is this the first time you ran borg compact on this repo? Thanks for the detailed info about it!

@ThomasWaldmann borg compact takes 11 minutes to run, so it's probably going to be hard to instrument the code and look for errors. But at least this suggests which part of the code to think about carefully... And maybe there are some sanity checks that could be added to the code as assertions that would help pinpoint the issue?

Jun 26 '22 16:06 jdchristensen

@jdchristensen : I use borg since 2018. A backup runs in every hours via cron, if the machine is turned on. After the first run on every day runs a "borg prune" and a "borg check" via anacron. Borg check never found any errors. The repo is on a partition of the hard disk, which is mounted to /backup. I copy the repo (via rsync) to an external USB disk, to a micro SD card and to a remote PC via SSH in every month, sometimes - if I work a lot - more frequently. I had never disk error as I can remember. Sometimes I had a disk full situation on the root partition (not on the backup) which could affect the /root directory. (And so the borg cache on it, because borg runs as root.) I never needed to restore the repo from any external source. If I need to restore some files from backup, I usually use borg mount. There was the first run of the "borg compact" now because my repo didn't fit to my 128G SD card. (Which I don't understand exactly because repo dir was about 70G only. Maybe it is due the encryption.) Did I forget something? Ask me. I'm glad to help make borg better.

Jun 27 '22 07:06 DSpammy

May I ask some help? What is the safest method if I would like to use my old repo for testing? Current and old repo have same id, so it is not so simple. I don't want to damage my current repo again.

Jun 27 '22 13:06 DSpammy

You can change the repo id in the config file in the borg repo you saved for testing. (Note that in general there are some risks if you do this with encrypted repos and plan to continue using both. But in this situation it should be fine.)

Jun 27 '22 14:06 jdchristensen

I played with my old backup in last days. I made run copy_original_repo-purge-compact-check cycles to check which archives are affected these errors. (This was a time consuming play because one cycle runtime was about 50 minutes.) I wanted to determine the affected archives via interval halving. The results are interesting and may help you. Here is a simple table with results:

purge keep-last count / error count / comment, if any

99 / 4 / not purged at all, there is four errors as listed earlier 98 / 3 / the third of the four errors disappeared ... 96 / 3 95 / 2 / an another (last of the three) error disappeared ... 81 / 2 80 / 3 / A NEW ERROR APPEARED after purge --keep-last 80 !! ... 75 / 3 74 / 1 / two errors disappeared, only the new appears 73 / 1 72 / 0 / there were no errors at --keep-last 72 and below

There were borg updates during this four years and unfortunately I can't say which borg version was used to backup these archives. (Except if the archive doesn't contain it and you tell me how can I to see it.)

I hope I could help. (To make chaos;)

Jul 05 '22 19:07 DSpammy

@DSpammy if you simplify your reproducer script by removing --cleanup-commits from the borg compact invocation, does it still reproduce the issue?

Jul 30 '22 13:07 ThomasWaldmann

@ThomasWaldmann The result is same as with --cleanup-commits. There is no difference.

Jul 30 '22 14:07 DSpammy

@DSpammy can you use the code from #6918 and run borg compact with --debug?

Jul 31 '22 17:07 ThomasWaldmann

Perhaps I can, but I need some help. My current borg version is 1.2.1, which is the latest version on Manjaro now. I downloaded the borg-compaction-debugging-1.2.zip file. May I simply replace (temporarily) repository.py, archive.py, archiver.py and base.py with downloaded files?

Jul 31 '22 20:07 DSpammy

You can either take the repository.py file and copy it over the original one or apply the patch.

Jul 31 '22 20:07 ThomasWaldmann

I copied repository.py first but when I run there was an exception related to archiver.py if I can remember. Then I copied each of the four files. After that I got the following message at borg check (before prune and compact): Starting repository check Old config file not securely erased on previous config update Local Exception Traceback (most recent call last): File "/usr/lib/python3.10/site-packages/borg/archiver.py", line 5159, in main exit_code = archiver.run(args) File "/usr/lib/python3.10/site-packages/borg/archiver.py", line 5090, in run return set_ec(func(args)) File "/usr/lib/python3.10/site-packages/borg/archiver.py", line 183, in wrapper return method(self, args, repository=repository, **kwargs) File "/usr/lib/python3.10/site-packages/borg/archiver.py", line 343, in do_check if not repository.check(repair=args.repair, save_space=args.save_space, max_duration=args.max_duration): File "/usr/lib/python3.10/site-packages/borg/repository.py", line 1026, in check self.save_config(self.path, self.config) File "/usr/lib/python3.10/site-packages/borg/repository.py", line 305, in save_config secure_erase(old_config_path, avoid_collateral_damage=True) TypeError: secure_erase() got an unexpected keyword argument 'avoid_collateral_damage'

Platform: Linux cornflower 5.10.133-1-MANJARO #1 SMP PREEMPT Mon Jul 25 20:12:34 UTC 2022 x86_64 Linux: Unknown Linux
Borg: 1.2.1 Python: CPython 3.10.5 msgpack: 1.0.3 fuse: llfuse 1.4.1 [pyfuse3,llfuse] PID: 1800 CWD: /root sys.argv: ['/usr/bin/borg', 'check', '-v', '--repository-only', '/backup/borg-old'] SSH_ORIGINAL_COMMAND: None

Maybe I made something wrong. I will try again later but now I have no time for that.

Aug 01 '22 15:08 DSpammy

Hmm, yeah, there were changes in other parts of the code also, so just applying the patch would work, but taking the whole repository.py does not.

Aug 01 '22 15:08 ThomasWaldmann

Patch:

commit e5b6670bc662882d3961808a0ed6c3d0af574ba6 (origin/compaction-debugging-1.2, compaction-debugging-1.2)
Author: Thomas Waldmann <[email protected]>
Date:   Sun Jul 31 19:01:09 2022 +0200

    repository: add debug logging for issue #6687
    
    i suspect that compact_segments wrongly drops some DEL tags.
    
    this could make already deleted chunks re-appear, leading to:
    - suddenly more repo index entries than previously (check, repo part)
    - suddenly orphaned chunks appearing (check, archives part)
    
    if this is the case, the issue is harmless, but annoying/confusing.
    
    to fix the issue, i need the complete log line "dropping DEL for id X".
    the id X it mentions is one of the chunk ids borg check complains about.

diff --git a/src/borg/repository.py b/src/borg/repository.py
index b7f32f9f..814f9b03 100644
--- a/src/borg/repository.py
+++ b/src/borg/repository.py
@@ -817,9 +817,10 @@ def complete_xfer(intermediate=True):
                 elif tag == TAG_DELETE and not in_index:
                     # If the shadow index doesn't contain this key, then we can't say if there's a shadowed older tag,
                     # therefore we do not drop the delete, but write it to a current segment.
-                    shadowed_put_exists = key not in self.shadow_index or any(
-                        # If the key is in the shadow index and there is any segment with an older PUT of this
-                        # key, we have a shadowed put.
+                    key_not_in_shadow_index = key not in self.shadow_index
+                    # If the key is in the shadow index and there is any segment with an older PUT of this
+                    # key, we have a shadowed put.
+                    shadowed_put_exists = key_not_in_shadow_index or any(
                         shadowed < segment for shadowed in self.shadow_index[key])
                     delete_is_not_stable = index_transaction_id is None or segment > index_transaction_id
 
@@ -865,6 +866,10 @@ def complete_xfer(intermediate=True):
                         self.compact[new_segment] += size
                         segments.setdefault(new_segment, 0)
                     else:
+                        logger.debug('dropping DEL for id %s - seg %d, iti %r, knisi %r, spe %r, dins %r, si %r',
+                                     bin_to_hex(key), segment, index_transaction_id,
+                                     key_not_in_shadow_index, shadowed_put_exists, delete_is_not_stable,
+                                     self.shadow_index.get(key))
                         # we did not keep the delete tag for key (see if-branch)
                         if not self.shadow_index[key]:
                             # shadowed segments list is empty -> remove it

Aug 04 '22 17:08 ThomasWaldmann

Here is the result of the "borg compact --cleanup-commits --debug ..." command:

borg-compact-debug.txt

And the result of "borg check":

borg-check.txt

Before compacting there were no errors.

Aug 06 '22 20:08 DSpammy

The three segment files that gave errors were 48506 (twice), 47096, 26597. All three were not compacted during the borg compact run. Interesting...

Aug 07 '22 00:08 jdchristensen

it dropped 1st DEL for e92b from segment 49494 because 48506 was not in the shadow_index, see si [49862].

it dropped 2nd DEL for e92b from segment 50870 because shadow_index was empty at that time, see si [].

after all the DELs were gone, e92b was undeleted.

if borg check would have been executed with --repair, I suspect it would have complained about orphan chunks (e.g. e92b) and would have deleted them again.

i don't know yet why the shadow index is wrong.

Aug 07 '22 16:08 ThomasWaldmann

Yes, "borg check --repair" could repair the repo. I use that repo since repair without problems.

Aug 07 '22 17:08 DSpammy

Did it complain about orphans (in the archives checking part) as I suspected above?

Aug 07 '22 17:08 ThomasWaldmann

Yes, It did. I checked again. borg-check-repair.txt

Aug 07 '22 17:08 DSpammy

I would just report that this problem still exists in borg version 1.2.2.

Oct 02 '22 09:10 DSpammy

This fix was not included in 1.2.2, you have to wait for 1.2.3 I guess

Oct 02 '22 09:10 infectormp

@infectormp Is there a known fix? As far as I know, this hasn't been debugged yet. I've been running with --debug on one machine for a while, and haven't seen the problem since I switched to the version with --debug. But on other machines, I still get the problem very frequently.

Oct 02 '22 13:10 jdchristensen

I get the issue as well unfortunately. Is more info needed to help debugging this?

Dec 10 '22 17:12 szaimen

@szaimen guess I would need a repo copy where the issue can be reproduced. I tried to track this down by logs (see above) and reading source code, but did not really find a problem yet.

And maybe I even need the state before any issue is introduced and the action that introduces the issue.

Dec 11 '22 20:12 ThomasWaldmann

@szaimen guess I would need a repo copy where the issue can be reproduced. I tried to track this down by logs (see above) and reading source code, but did not really find a problem yet.

Okay, actually I indeed have a testrepo and will try to reproduce the issue with that. I'll let you know how it goes and will let you know the exact steps if I should suceed.

Dec 11 '22 20:12 szaimen

Unfortunately I wasn't able to reproduce the issue with my test-archive. :/

Dec 13 '22 10:12 szaimen

Likely related to #5661.

Oct 28 '23 19:10 ThomasWaldmann

borg borg copied to clipboard

borg compact makes my repo wrong

Have you checked borgbackup docs, FAQ, and open Github issues?

Is this a BUG / ISSUE report or a QUESTION?

System information. For client/server mode post info for both machines.

Your borg version (borg -V).

Operating system (distribution) and version.

Hardware / network configuration, and filesystems used.

How much data is handled by borg?

Full borg commandline that lead to the problem (leave away excludes and passwords)

Describe the problem you're observing.

Can you reproduce the problem? If so, describe how. If not, describe troubleshooting steps you took before opening the issue.

Include any warning/errors/backtraces from the system logs

borg
borg copied to clipboard