Release 1.2.0b4 - beta quality, for testing only

[ThomasWaldmann]

borgbackup 1.2.0b4 beta release - do not use this on production backup repositories.

Long changelog:
https://github.com/borgbackup/borg/blob/1.2.0b4/docs/changes.rst#version-120b4-2022-01-23

If you use pip to install this, use: pip install "borgbackup==1.2.0b4"

Please give feedback in the related github discussion!

---

This discussion was created from the release Release 1.2.0b4 - beta quality, for testing only.

[m3nu]

Here the result of the testing I did so far:

• Build on macOS: yes, with BORG_OPENSSL_PREFIX=/usr/local/Cellar/openssl@1.1/1.1.1m/
• Vorta runs all tests with 1.2.0b4
• Upgrade Homebrew formula (non-FUSE): yes, with msgpack as new dependency

[bket]

I'm testing 1.2.0b4 on OpenBSD current. So far, it builds and passes all regression tests except the one below.

=================================== FAILURES ===================================
_ RemoteArchiverTestCase.test_do_not_mention_archive_if_you_can_not_find_repo __

self = <borg.testsuite.archiver.RemoteArchiverTestCase testMethod=test_do_not_mention_archive_if_you_can_not_find_repo>

    def test_do_not_mention_archive_if_you_can_not_find_repo(self):
        """https://github.com/borgbackup/borg/issues/6014"""
        archive = self.repository_location + '-this-repository-does-not-exist' + '::test'
        output = self.cmd('info', archive, exit_code=2, fork=True)
        self.assert_in('this-repository-does-not-exist', output)
>       self.assert_not_in('this-repository-does-not-exist::test', output)
E       AssertionError: 'this-repository-does-not-exist::test' unexpectedly found in 'Repository __testsuite__:/tmp/tmpwytqjmvn/repository-this-repository-does-not-exist::test does not exist.\n'

lib.openbsd-7.0-amd64-3.9/borg/testsuite/archiver.py:3940: AssertionError
============= 1 failed, 1206 passed, 254 skipped in 969.46 seconds =============

Typical actions, e.g. init / create / list / prune, seem to work as advertised. import-tar is nice to have! Will report back when something pops up.

[ThomasWaldmann]

@bket huh, that is strange.

i ran platform testing on a lot of systems (misc. linux, openbsd, netbsd, macos, openindiana) and that one did not pop up for me.

also, if only that one failed for you, does that mean that the same test in ArchiverTestCase worked and only the one in RemoteArchiverTestCase failed?

Besides that, I would not expect a platform dependency here, which makes this even more strange.

can you reproduce this failure?

[bket]

@tw, of course this failing test could be the result of me being stupid.

also, if only that one failed for you, does that mean that the same test in ArchiverTestCase worked and only the one in RemoteArchiverTestCase failed?

I captured the output while testing (test.log). It seems that this test is only used in RemoteArchiverTestCase. At least there is no other mentioning about it.

$ grep ::test_do_not_mention_archive_if_you_can_not_find_repo test.log
src/borg/testsuite/archiver.py::RemoteArchiverTestCase::test_do_not_mention_archive_if_you_can_not_find_repo FAILED [ 33%]

can you reproduce this failure?

Yes.

[ThomasWaldmann]

see #6168

[bket]

@tw, after some digging I found that the failing test is my fault. I had borgbackup-1.1.17 in my path, which was interfering. Issue has been resolved, and all tests pass.

I also checked #6168, which works for me.

$ grep do_not_mention test.log  
src/borg/testsuite/archiver.py::ArchiverTestCase::test_do_not_mention_archive_if_you_can_not_find_repo PASSED [  7%]
src/borg/testsuite/archiver.py::ArchiverTestCaseBinary::test_do_not_mention_archive_if_you_can_not_find_repo SKIPPED [ 19%]
src/borg/testsuite/archiver.py::RemoteArchiverTestCase::test_do_not_mention_archive_if_you_can_not_find_repo PASSED [ 33%]

Sorry for the noise!

[ThomasWaldmann]

hmm, so the tests invoked some "borg" that just happened to be in $PATH?

guess we do not require a test system to be borg-free, so that might be a bug (which i maybe never found because i use virtualenv?).

[m3nu]

I ran into one thing that surprised me a bit:

When running borg create with either --json or --stats, it will go wild and download data for 30+min to calculate statistics for each single archive. Looks like below. As you see it counts to 100% and then starts again (with a different archive??). If this is intentional, we can't show --stats any more in Vorta.

{"operation": 2, "msgid": "cache.commit", "type": "progress_message", "finished": true, "time": 1643096525.9040499}
{"message": "Calculating statistics...   0%", "current": 1, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096526.9258208}
{"message": "Calculating statistics...   5%", "current": 106, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096539.237629}
{"message": "Calculating statistics...  10%", "current": 210, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096561.898442}
{"message": "Calculating statistics...  15%", "current": 314, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096565.4991071}
{"message": "Calculating statistics...  20%", "current": 418, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096568.3276238}
{"message": "Calculating statistics...  25%", "current": 522, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096570.8732748}
{"message": "Calculating statistics...  30%", "current": 626, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096573.855891}
{"message": "Calculating statistics...  35%", "current": 730, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096576.426215}
{"message": "Calculating statistics...  40%", "current": 834, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096579.273066}
{"message": "Calculating statistics...  45%", "current": 938, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096583.145403}
{"message": "Calculating statistics...  50%", "current": 1042, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096586.947915}
{"message": "Calculating statistics...  55%", "current": 1146, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096590.162051}
{"message": "Calculating statistics...  60%", "current": 1250, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096592.730772}
{"message": "Calculating statistics...  65%", "current": 1354, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096595.540685}
{"message": "Calculating statistics...  70%", "current": 1458, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096598.215549}
{"message": "Calculating statistics...  75%", "current": 1562, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096600.879049}
{"message": "Calculating statistics...  80%", "current": 1666, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096616.674206}
{"message": "Calculating statistics...  85%", "current": 1770, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096627.5413299}
{"message": "Calculating statistics...  90%", "current": 1874, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096631.93779}
{"message": "Calculating statistics...  95%", "current": 1978, "total": 2081, "info": null, "operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096635.176608}
{"operation": 1, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": true, "time": 1643096638.181329}
{"message": "Calculating statistics...   0%", "current": 1, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096638.829045}
{"message": "Calculating statistics...   5%", "current": 105, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096640.762101}
{"message": "Calculating statistics...  10%", "current": 209, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096643.798684}
{"message": "Calculating statistics...  15%", "current": 313, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096646.822568}
{"message": "Calculating statistics...  20%", "current": 417, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096649.9047658}
{"message": "Calculating statistics...  25%", "current": 521, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096652.928701}
{"message": "Calculating statistics...  30%", "current": 625, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096656.068079}
{"message": "Calculating statistics...  35%", "current": 729, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096659.925112}
{"message": "Calculating statistics...  40%", "current": 833, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096663.7652428}
{"message": "Calculating statistics...  45%", "current": 937, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096667.194601}
{"message": "Calculating statistics...  50%", "current": 1040, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096671.073945}
{"message": "Calculating statistics...  55%", "current": 1144, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096674.115019}
{"message": "Calculating statistics...  60%", "current": 1248, "total": 2078, "info": null, "operation": 2, "msgid": "archive.calc_stats", "type": "progress_percent", "finished": false, "time": 1643096677.175528}

[ThomasWaldmann]

#6296 < fixed!

[ThomasWaldmann]

except that it will be still slow at first invocation (borg info or create --stats) when it builds the cache.

[FabioPedretti]

Do you think it would be possible to fix the 1.1 branch so than from 1.1.18 archives are already generated with the correct "1.2" format and won't need to be updated? Thanks.

[ThomasWaldmann]

btw, guess I need to fix that progress display. either add the archive name or n/N or remove it completely.

[ThomasWaldmann]

@FabioPedretti

Do you think it would be possible to fix the 1.1 branch so than from 1.1.18 archives are already generated with the correct "1.2" format and won't need to be updated?

Good idea in principle, but IIRC that was a bigger and not-so-easy change, so guess that's why I didn't flag it for backporting to 1.1-maint.

With my recent PR which fixes the slowness by introducing a small client-local cache for the missing metadata in 1.1 archives, the only discomfort is that the first "borg info" (or other stats) on a repo will take rather long, but after that it is super quick.

After users have switched to 1.2, the amount of 1.1 archives will quickly decrease. But it will take a really long time for some until the last 1.1 archives will be pruned (esp. if one has multi-years retention rules), so in 1.2+ that cache is a good solution.

I will also have a look at recreate, whether it adds / could add the new metadata when it is used on a 1.1 archive, that could be another option (but way more expensive than building the cache). recreate runs clientside, so does a lot of I/O and processing.

[ThomasWaldmann]

Do you think it would be possible to fix the 1.1 branch so than from 1.1.18 archives are already generated with the correct "1.2" format and won't need to be updated? Thanks.

Good idea in principle, but IIRC that was a bigger and not-so-easy change, so guess that's why I didn't flag it for backporting to 1.1-maint. With my recent PR which fixes the slowness by introducing a small client-local cache for the missing metadata in 1.1 archives, the only discomfort is that the first "borg info" (or other stats) on a repo will take rather long, but after that it is super quick. After users have switched to 1.2, the amount of 1.1 archives will quickly decrease. But it will take a really long time for some until the last 1.1 archives will be pruned (esp. if one has multi-years retention rules), so in 1.2+ that cache is a good solution. I will also have a look at recreate, whether it adds / could add the new metadata when it is used on a 1.1 archive, that could be another option (but way more expensive than building the cache).