Why does kopiaUI fails to create snapshot on macOS 11.2.1?

Support
1

I have recently updated to macOS to 11.2.1 and since then I do have an issue with one of my two Kopia backups. I do two backups, one on a USB3 NVMe drive and one to a Kopia server, which hosts it’s repo on a ZFS volume.

The erron in the cli-log shows this, when the snapshot fails on the Kopia server:

2021-02-12 21:57:09.662 W [local_fs.go:198] unable to create directory entry "Commands": unsupported filesystem entry: &{Commands 0 16777600 {993978202 63748644974 0x2642240} {16777220 49536 1 51515166 502 20 0 [0 0 0 0] {1613048174 993978202} {1613048174 993978202} {1613048174 994150887} {1613048174 993978202} 0 0 4096 0 0 0 [0 0]}}
2021-02-12 21:57:09.662 W [local_fs.go:198] unable to create directory entry "Notification": unsupported filesystem entry: &{Notification 0 16777600 {877794073 63748644974 0x2642240} {16777220 49536 1 51515151 502 20 0 [0 0 0 0] {1613048174 877794073} {1613048174 877794073} {1613048174 877977408} {1613048174 877794073} 0 0 4096 0 0 0 [0 0]}}
2021-02-12 21:57:17.782 W [local_fs.go:198] unable to create directory entry "default.realm.note": unsupported filesystem entry: &{default.realm.note 0 33554816 {824671423 63748623947 0x2642240} {16777220 4480 1 51485064 502 20 0 [0 0 0 0] {1613026828 475095138} {1613027147 824671423} {1613027147 824671423} {1613026828 475095138} 0 0 4096 0 0 0 [0 0]}}
2021-02-12 21:57:17.783 W [local_fs.go:198] unable to create directory entry "access_control.pick_writer.cv": unsupported filesystem entry: &{access_control.pick_writer.cv 0 33554816 {474623863 63748623628 0x2642240} {16777220 4480 1 51485063 502 20 0 [0 0 0 0] {1613026828 474623863} {1613026828 474623863} {1613026828 474623863} {1613026828 474623863} 0 0 4096 0 0 0 [0 0]}}
2021-02-12 21:57:17.783 W [local_fs.go:198] unable to create directory entry "access_control.new_commit.cv": unsupported filesystem entry: &{access_control.new_commit.cv 0 33554816 {474382534 63748623628 0x2642240} {16777220 4480 1 51485062 502 20 0 [0 0 0 0] {1613026828 474382534} {1613026828 474382534} {1613026828 474382534} {1613026828 474382534} 0 0 4096 0 0 0 [0 0]}}
2021-02-12 21:57:36.950 W [local_fs.go:198] unable to create directory entry "IPC socket": unsupported filesystem entry: &{IPC socket 0 16777709 {398993770 63748644977 0x2642240} {16777220 49645 1 51515371 502 20 0 [0 0 0 0] {1613048177 398993770} {1613048177 398993770} {1613048177 399048923} {1613048177 398993770} 0 0 4096 0 0 0 [0 0]}}
2021-02-12 21:58:04.667 D [apiclient.go:182] PUT https://10.10.0.252:5151/api/v1/contents/kbb810fe95cf5421bea52471ded5f3c0b took 58.621280891s and failed with read tcp 10.10.0.106:57755->10.10.0.252:5151: read: operation timed out
2021-02-12 21:58:04.710 D [apiclient.go:186] POST https://10.10.0.252:5151/api/v1/flush took 41.249344ms and returned 200 OK
2021-02-12 21:58:04.712 D [memory_tracking.go:31] in use heap 21094400 (delta 21094400 max 0) stack 2785280 (delta 2785280 max 0)

Soo… “read: operation timed out”, is this on the client or the server?

2

Is this a one-time blip or happening consistently?

Kopia appears to be waiting for response from the server and timing out.

3

Okay… however, this always seems to happen at the same objects, KopiaUI tries to check. How can I dig into this further - I’d rather like to keep my server repo and not wipe it out. This also doesn’t seem to be a problem with the server itself, since my other KopiaUI client runs just fine, with the same repo.

4

Is it always the first object that’s causing trouble?

5

It goes to 292.4GB from 703.5 GB and then stalls. When I look at the content-logs there is still something going on, but it seems that these lines seem to be repeated over and over again:

2021-02-14 08:49:34.8819637 list-from-cache 'm' found 2
2021-02-14 08:49:34.8822984 list-from-cache 'n' found 18
2021-02-14 08:49:34.8824397 found-index-blobs[0] = {n37f5523bc1d1e82be8b9515c77a4a46e 28924 2021-02-14 03:00:53.291351759 +0100 CET}
2021-02-14 08:49:34.8824762 found-index-blobs[1] = {n5e0ced139e05bacb955142e0cf858c65 434 2021-02-14 06:01:04.211343712 +0100 CET}
2021-02-14 08:49:34.8824990 found-index-blobs[2] = {n5f675182c240e365ffbacd00d79a1e21 28924 2021-02-14 01:00:46.142891512 +0100 CET}
2021-02-14 08:49:34.8825192 found-index-blobs[3] = {n61d5ed54f8d2875ac3a6ad254a57ed92 73801 2021-02-14 08:26:16.699611908 +0100 CET}
2021-02-14 08:49:34.8825397 found-index-blobs[4] = {nb773ea2089bb30d933f8023b8901376e 24448483 2021-02-12 22:59:05.352350625 +0100 CET}
2021-02-14 08:49:34.8825618 found-index-blobs[5] = {n4d03c9f598513abaa9d178abcaa18290 1651 2021-02-14 08:26:16.623611614 +0100 CET}
2021-02-14 08:49:34.8825802 found-index-blobs[6] = {n4ec1311c463e9d05762044b2956e7aaf 1242181 2021-02-13 01:59:21.884899148 +0100 CET}
2021-02-14 08:49:34.8825996 found-index-blobs[7] = {n2e605f363d5134c1eabb178fa240a68c 132445 2021-02-13 23:00:40.759665884 +0100 CET}
2021-02-14 08:49:34.8826206 found-index-blobs[8] = {n8ebc6ed2a60a8ad4c5069de7e84c8fd8 28924 2021-02-14 05:01:00.535118926 +0100 CET}
2021-02-14 08:49:34.8826401 found-index-blobs[9] = {nb8da1d59b540f5d84496a324769d6f51 434 2021-02-14 08:01:11.034359507 +0100 CET}
2021-02-14 08:49:34.8826599 found-index-blobs[10] = {nce5045e67190f4f7495ad7bed5c9ed12 34396437 2021-01-15 15:34:07.659534994 +0100 CET}
2021-02-14 08:49:34.8826801 found-index-blobs[11] = {nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}
2021-02-14 08:49:34.8826999 found-index-blobs[12] = {ne8eb27aaa11bde27aad2496e7eb97454 393 2021-02-14 02:00:49.762247742 +0100 CET}
2021-02-14 08:49:34.8827192 found-index-blobs[13] = {n2c60915d488fb68afbb8aca0e7bb8850 1061680 2021-02-12 23:22:44.046074862 +0100 CET}
2021-02-14 08:49:34.8827390 found-index-blobs[14] = {n2eba96cec3de8b5fdc603aa73925f542 471 2021-02-14 08:36:35.585882788 +0100 CET}
2021-02-14 08:49:34.8827589 found-index-blobs[15] = {n4e25d7c7bea1663cd80f956fbb10e772 578 2021-02-14 04:00:56.851436302 +0100 CET}
2021-02-14 08:49:34.8827787 found-index-blobs[16] = {n6aaf63fa02ceb9365d3cf4e4041eb7da 25338 2021-02-14 08:11:23.552334724 +0100 CET}
2021-02-14 08:49:34.8827975 found-index-blobs[17] = {na8df0dc1a33f6aae8990020e8f1471ff 28924 2021-02-14 07:01:07.614897224 +0100 CET}
2021-02-14 08:49:34.8828174 found-compaction-blobs[0] {m49f4fe406e7b6cd760df80be346f810e 820 2021-02-14 05:01:02.567126042 +0100 CET}
2021-02-14 08:49:34.8828511 found-compaction-blobs[1] {mf625506e2a317340ee451f0c9398c6c1 823 2021-02-13 23:00:40.759665884 +0100 CET}
2021-02-14 08:49:34.8831720 ignore-index-blob {n4e25d7c7bea1663cd80f956fbb10e772 578 2021-02-14 04:00:56.851436302 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:34.8832154 ignore-index-blob {n37f5523bc1d1e82be8b9515c77a4a46e 28924 2021-02-14 03:00:53.291351759 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:34.8832423 ignore-index-blob {n5f675182c240e365ffbacd00d79a1e21 28924 2021-02-14 01:00:46.142891512 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:34.8832670 ignore-index-blob {n8ebc6ed2a60a8ad4c5069de7e84c8fd8 28924 2021-02-14 05:01:00.535118926 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:34.8832917 ignore-index-blob {ne8eb27aaa11bde27aad2496e7eb97454 393 2021-02-14 02:00:49.762247742 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:34.8833154 ignore-index-blob {n2e605f363d5134c1eabb178fa240a68c 132445 2021-02-13 23:00:40.759665884 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:34.8833483 active-index-blobs[0] = {{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET} []}
2021-02-14 08:49:34.8833719 active-index-blobs[1] = {{n5e0ced139e05bacb955142e0cf858c65 434 2021-02-14 06:01:04.211343712 +0100 CET} []}
2021-02-14 08:49:34.8833934 active-index-blobs[2] = {{nce5045e67190f4f7495ad7bed5c9ed12 34396437 2021-01-15 15:34:07.659534994 +0100 CET} []}
2021-02-14 08:49:34.8834149 active-index-blobs[3] = {{nb8da1d59b540f5d84496a324769d6f51 434 2021-02-14 08:01:11.034359507 +0100 CET} []}
2021-02-14 08:49:34.8834388 active-index-blobs[4] = {{n2eba96cec3de8b5fdc603aa73925f542 471 2021-02-14 08:36:35.585882788 +0100 CET} []}
2021-02-14 08:49:34.8834599 active-index-blobs[5] = {{nb773ea2089bb30d933f8023b8901376e 24448483 2021-02-12 22:59:05.352350625 +0100 CET} []}
2021-02-14 08:49:34.8834802 active-index-blobs[6] = {{n4d03c9f598513abaa9d178abcaa18290 1651 2021-02-14 08:26:16.623611614 +0100 CET} []}
2021-02-14 08:49:34.8835008 active-index-blobs[7] = {{n4ec1311c463e9d05762044b2956e7aaf 1242181 2021-02-13 01:59:21.884899148 +0100 CET} []}
2021-02-14 08:49:34.8835209 active-index-blobs[8] = {{n2c60915d488fb68afbb8aca0e7bb8850 1061680 2021-02-12 23:22:44.046074862 +0100 CET} []}
2021-02-14 08:49:34.8835412 active-index-blobs[9] = {{na8df0dc1a33f6aae8990020e8f1471ff 28924 2021-02-14 07:01:07.614897224 +0100 CET} []}
2021-02-14 08:49:34.8835616 active-index-blobs[10] = {{n6aaf63fa02ceb9365d3cf4e4041eb7da 25338 2021-02-14 08:11:23.552334724 +0100 CET} []}
2021-02-14 08:49:34.8835823 active-index-blobs[11] = {{n61d5ed54f8d2875ac3a6ad254a57ed92 73801 2021-02-14 08:26:16.699611908 +0100 CET} []}
2021-02-14 08:49:34.8836173 index-already-cached nce7a084e3dc29371da6a68b953305780
2021-02-14 08:49:34.8836461 index-already-cached n5e0ced139e05bacb955142e0cf858c65
2021-02-14 08:49:34.8836723 index-already-cached nce5045e67190f4f7495ad7bed5c9ed12
2021-02-14 08:49:34.8837003 index-already-cached nb8da1d59b540f5d84496a324769d6f51
2021-02-14 08:49:34.8837279 index-already-cached n2eba96cec3de8b5fdc603aa73925f542
2021-02-14 08:49:34.8837529 index-already-cached nb773ea2089bb30d933f8023b8901376e
2021-02-14 08:49:34.8837772 index-already-cached n4d03c9f598513abaa9d178abcaa18290
2021-02-14 08:49:34.8838023 index-already-cached n4ec1311c463e9d05762044b2956e7aaf
2021-02-14 08:49:34.8838282 index-already-cached n2c60915d488fb68afbb8aca0e7bb8850
2021-02-14 08:49:34.8838535 index-already-cached na8df0dc1a33f6aae8990020e8f1471ff
2021-02-14 08:49:34.8838781 index-already-cached n6aaf63fa02ceb9365d3cf4e4041eb7da
2021-02-14 08:49:34.8839027 index-already-cached n61d5ed54f8d2875ac3a6ad254a57ed92
2021-02-14 08:49:39.7645792 write-content k2f50a2e2b2eeb2224410391e68e877f1 already-exists
2021-02-14 08:49:39.7720494 write-content kf6aaadc6c2ec32cb436377e0c35f6749 already-exists
2021-02-14 08:49:39.7735239 write-content kd79aa4f9ea26443531e9653bb7cb8339 already-exists
2021-02-14 08:49:39.7784897 write-content k5df1b7d85b7ee620efe9683cace19295 already-exists
2021-02-14 08:49:39.7796622 write-content k6d9dd294ec8eb873b02ff13b3dc41e00 already-exists
2021-02-14 08:49:39.7841183 write-content kca6bf9ddfadb8b785e4c46fa939fdb64 already-exists
2021-02-14 08:49:39.7853042 write-content k9f55dbb0f913e2500e5ed77a7a8b1416 already-exists
2021-02-14 08:49:39.7897091 write-content kaa8bfce25f8a576433b7f182f46dd234 already-exists
2021-02-14 08:49:39.7908789 write-content k915d29bc43a909e152f35e1d4ed421b8 already-exists
2021-02-14 08:49:39.7954290 write-content k4267efa2759d33e090119fa10c8ec705 already-exists
2021-02-14 08:49:39.7966242 write-content kac599f030b0ccebd491dc1538be91eb6 already-exists
2021-02-14 08:49:39.8010272 write-content k39783c684ae1cffb0fd271f5268c311d already-exists
2021-02-14 08:49:39.8022728 write-content kb0c15ae6d558c197215d45b34abaa2b1 already-exists
2021-02-14 08:49:39.8063285 write-content kca827f36691c05c4ed3ca5b01fa75079 already-exists
2021-02-14 08:49:39.8074382 write-content kda76b026d205b573a2fc505862d94e36 already-exists
2021-02-14 08:49:39.8117556 write-content k8c473efc540fcf3f6faaaa2e56299310 already-exists
2021-02-14 08:49:39.8128694 write-content k0998b4d8265faab845f58b7dde0e86a0 already-exists
2021-02-14 08:49:39.8168853 write-content kbb399f967e81f1596b42fd3f10586335 already-exists
2021-02-14 08:49:39.8180064 write-content k57a150caae79b2e60fb199e8fc5116e7 already-exists
2021-02-14 08:49:39.8223293 write-content k31de5dde55fd56a3537d449a005e3c80 already-exists
2021-02-14 08:49:39.8235783 write-content kf8d577fa4d5d2790e5877033093ee95d already-exists
2021-02-14 08:49:39.8276011 write-content k819c6d440a9c5a1a0441ecb24aa9cba2 already-exists
2021-02-14 08:49:39.8287614 write-content kb9e4a3c4a0bf0bcf6f10b878a7e2cb22 already-exists
2021-02-14 08:49:39.8330736 write-content k42f88567e106d66355603b8a7405152c already-exists
2021-02-14 08:49:39.8342684 write-content k4507886b6d78c3f1825d44ed89b8fea6 already-exists
2021-02-14 08:49:39.8386005 write-content k5a55b48dbe86fcc87c0def819b48aeff already-exists
2021-02-14 08:49:39.8398315 write-content k20d5bc32a65d2268ca49959e776372fd already-exists
2021-02-14 08:49:39.8440873 write-content k6e765d2d5f3cdaac606689dfc7de3e1c already-exists
2021-02-14 08:49:39.8451930 write-content kc6961cd5d8df331a286070383d2de09d already-exists
2021-02-14 08:49:39.8493531 write-content k5795e97ca8a3aa0e119805aa3503c5de already-exists
2021-02-14 08:49:39.8505397 write-content ka410994c1b730af7fdd134fd62fecd4f already-exists
2021-02-14 08:49:39.8546371 write-content k4f45e542dbff95d63e4a783c1ae6905a already-exists
2021-02-14 08:49:39.8559569 write-content k557df16fd60e800717d46e09cf707543 already-exists
2021-02-14 08:49:39.8605921 write-content kd9c99d402f4a446e725bd6999c689a18 already-exists
2021-02-14 08:49:39.8617822 write-content kcf5947c0b3f48f64f740a96014f0e795 already-exists
2021-02-14 08:49:39.8664722 write-content k70fe8e21497670372857b31845f0a4c9 already-exists
2021-02-14 08:49:39.8676940 write-content k72099e7ad5500723793bdbf36b87f036 already-exists
2021-02-14 08:49:39.8724507 write-content k31c1fc15dd186f935d0c5f6b12874577 already-exists
2021-02-14 08:49:39.8735729 write-content k88955f0d0cfe808ef3d01d0875515fcc already-exists
2021-02-14 08:49:39.8781120 write-content k0563829a1da8bac018d2cabd87406bea already-exists
2021-02-14 08:49:39.8792923 write-content kf59a23c8d43ca111b55140aebd8d7072 already-exists
2021-02-14 08:49:39.8843018 write-content ke2871b55ef02a406d26c80d6f1a88125 already-exists
2021-02-14 08:49:39.8854799 write-content k86cfcd95bf50f225ebaf65fabf72d6fe already-exists
2021-02-14 08:49:39.8897091 write-content k74325b6923ce7d0bdd814edda994ba1a already-exists
2021-02-14 08:49:39.8909251 write-content kc3b491846e86072f66f0e7b134f4a56b already-exists
2021-02-14 08:49:39.8955083 write-content k2a6f1e7ae701f51b39da17a933ed5b3b already-exists
2021-02-14 08:49:44.8846039 list-from-cache 'm' found 2
2021-02-14 08:49:44.8848387 list-from-cache 'n' found 18
2021-02-14 08:49:44.8849376 found-index-blobs[0] = {n2e605f363d5134c1eabb178fa240a68c 132445 2021-02-13 23:00:40.759665884 +0100 CET}
2021-02-14 08:49:44.8849615 found-index-blobs[1] = {n61d5ed54f8d2875ac3a6ad254a57ed92 73801 2021-02-14 08:26:16.699611908 +0100 CET}
2021-02-14 08:49:44.8849742 found-index-blobs[2] = {n8ebc6ed2a60a8ad4c5069de7e84c8fd8 28924 2021-02-14 05:01:00.535118926 +0100 CET}
2021-02-14 08:49:44.8849853 found-index-blobs[3] = {na8df0dc1a33f6aae8990020e8f1471ff 28924 2021-02-14 07:01:07.614897224 +0100 CET}
2021-02-14 08:49:44.8849960 found-index-blobs[4] = {nb773ea2089bb30d933f8023b8901376e 24448483 2021-02-12 22:59:05.352350625 +0100 CET}
2021-02-14 08:49:44.8850234 found-index-blobs[5] = {nb8da1d59b540f5d84496a324769d6f51 434 2021-02-14 08:01:11.034359507 +0100 CET}
2021-02-14 08:49:44.8850347 found-index-blobs[6] = {n2eba96cec3de8b5fdc603aa73925f542 471 2021-02-14 08:36:35.585882788 +0100 CET}
2021-02-14 08:49:44.8850468 found-index-blobs[7] = {n37f5523bc1d1e82be8b9515c77a4a46e 28924 2021-02-14 03:00:53.291351759 +0100 CET}
2021-02-14 08:49:44.8850577 found-index-blobs[8] = {n4d03c9f598513abaa9d178abcaa18290 1651 2021-02-14 08:26:16.623611614 +0100 CET}
2021-02-14 08:49:44.8850687 found-index-blobs[9] = {n6aaf63fa02ceb9365d3cf4e4041eb7da 25338 2021-02-14 08:11:23.552334724 +0100 CET}
2021-02-14 08:49:44.8850795 found-index-blobs[10] = {nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}
2021-02-14 08:49:44.8850904 found-index-blobs[11] = {n5f675182c240e365ffbacd00d79a1e21 28924 2021-02-14 01:00:46.142891512 +0100 CET}
2021-02-14 08:49:44.8851015 found-index-blobs[12] = {ne8eb27aaa11bde27aad2496e7eb97454 393 2021-02-14 02:00:49.762247742 +0100 CET}
2021-02-14 08:49:44.8851122 found-index-blobs[13] = {n2c60915d488fb68afbb8aca0e7bb8850 1061680 2021-02-12 23:22:44.046074862 +0100 CET}
2021-02-14 08:49:44.8851229 found-index-blobs[14] = {n4e25d7c7bea1663cd80f956fbb10e772 578 2021-02-14 04:00:56.851436302 +0100 CET}
2021-02-14 08:49:44.8851352 found-index-blobs[15] = {n4ec1311c463e9d05762044b2956e7aaf 1242181 2021-02-13 01:59:21.884899148 +0100 CET}
2021-02-14 08:49:44.8851464 found-index-blobs[16] = {n5e0ced139e05bacb955142e0cf858c65 434 2021-02-14 06:01:04.211343712 +0100 CET}
2021-02-14 08:49:44.8851574 found-index-blobs[17] = {nce5045e67190f4f7495ad7bed5c9ed12 34396437 2021-01-15 15:34:07.659534994 +0100 CET}
2021-02-14 08:49:44.8851691 found-compaction-blobs[0] {m49f4fe406e7b6cd760df80be346f810e 820 2021-02-14 05:01:02.567126042 +0100 CET}
2021-02-14 08:49:44.8851802 found-compaction-blobs[1] {mf625506e2a317340ee451f0c9398c6c1 823 2021-02-13 23:00:40.759665884 +0100 CET}
2021-02-14 08:49:44.8853718 ignore-index-blob {n4e25d7c7bea1663cd80f956fbb10e772 578 2021-02-14 04:00:56.851436302 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:44.8854052 ignore-index-blob {n37f5523bc1d1e82be8b9515c77a4a46e 28924 2021-02-14 03:00:53.291351759 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:44.8854297 ignore-index-blob {n5f675182c240e365ffbacd00d79a1e21 28924 2021-02-14 01:00:46.142891512 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:44.8854441 ignore-index-blob {n8ebc6ed2a60a8ad4c5069de7e84c8fd8 28924 2021-02-14 05:01:00.535118926 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:44.8854571 ignore-index-blob {ne8eb27aaa11bde27aad2496e7eb97454 393 2021-02-14 02:00:49.762247742 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:44.8854702 ignore-index-blob {n2e605f363d5134c1eabb178fa240a68c 132445 2021-02-13 23:00:40.759665884 +0100 CET} compacted to [{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET}]
2021-02-14 08:49:44.8854876 active-index-blobs[0] = {{n61d5ed54f8d2875ac3a6ad254a57ed92 73801 2021-02-14 08:26:16.699611908 +0100 CET} []}
2021-02-14 08:49:44.8855002 active-index-blobs[1] = {{na8df0dc1a33f6aae8990020e8f1471ff 28924 2021-02-14 07:01:07.614897224 +0100 CET} []}
2021-02-14 08:49:44.8855142 active-index-blobs[2] = {{nb773ea2089bb30d933f8023b8901376e 24448483 2021-02-12 22:59:05.352350625 +0100 CET} []}
2021-02-14 08:49:44.8855352 active-index-blobs[3] = {{nb8da1d59b540f5d84496a324769d6f51 434 2021-02-14 08:01:11.034359507 +0100 CET} []}
2021-02-14 08:49:44.8855562 active-index-blobs[4] = {{n2eba96cec3de8b5fdc603aa73925f542 471 2021-02-14 08:36:35.585882788 +0100 CET} []}
2021-02-14 08:49:44.8855760 active-index-blobs[5] = {{n2c60915d488fb68afbb8aca0e7bb8850 1061680 2021-02-12 23:22:44.046074862 +0100 CET} []}
2021-02-14 08:49:44.8855976 active-index-blobs[6] = {{n6aaf63fa02ceb9365d3cf4e4041eb7da 25338 2021-02-14 08:11:23.552334724 +0100 CET} []}
2021-02-14 08:49:44.8856099 active-index-blobs[7] = {{n5e0ced139e05bacb955142e0cf858c65 434 2021-02-14 06:01:04.211343712 +0100 CET} []}
2021-02-14 08:49:44.8856220 active-index-blobs[8] = {{n4d03c9f598513abaa9d178abcaa18290 1651 2021-02-14 08:26:16.623611614 +0100 CET} []}
2021-02-14 08:49:44.8856331 active-index-blobs[9] = {{n4ec1311c463e9d05762044b2956e7aaf 1242181 2021-02-13 01:59:21.884899148 +0100 CET} []}
2021-02-14 08:49:44.8856441 active-index-blobs[10] = {{nce7a084e3dc29371da6a68b953305780 133099 2021-02-14 05:01:02.567126042 +0100 CET} []}
2021-02-14 08:49:44.8856551 active-index-blobs[11] = {{nce5045e67190f4f7495ad7bed5c9ed12 34396437 2021-01-15 15:34:07.659534994 +0100 CET} []}
2021-02-14 08:49:44.8856780 index-already-cached n61d5ed54f8d2875ac3a6ad254a57ed92
2021-02-14 08:49:44.8856941 index-already-cached na8df0dc1a33f6aae8990020e8f1471ff
2021-02-14 08:49:44.8857084 index-already-cached nb773ea2089bb30d933f8023b8901376e
2021-02-14 08:49:44.8857228 index-already-cached nb8da1d59b540f5d84496a324769d6f51
2021-02-14 08:49:44.8857389 index-already-cached n2eba96cec3de8b5fdc603aa73925f542
2021-02-14 08:49:44.8857532 index-already-cached n2c60915d488fb68afbb8aca0e7bb8850
2021-02-14 08:49:44.8857671 index-already-cached n6aaf63fa02ceb9365d3cf4e4041eb7da
2021-02-14 08:49:44.8857810 index-already-cached n5e0ced139e05bacb955142e0cf858c65
2021-02-14 08:49:44.8857948 index-already-cached n4d03c9f598513abaa9d178abcaa18290
2021-02-14 08:49:44.8858096 index-already-cached n4ec1311c463e9d05762044b2956e7aaf
2021-02-14 08:49:44.8858244 index-already-cached nce7a084e3dc29371da6a68b953305780
2021-02-14 08:49:44.8858382 index-already-cached nce5045e67190f4f7495ad7bed5c9ed12
2021-02-14 08:49:54.4597862 write-content k44ea2c5678ff3880449442df39651892 already-exists
2021-02-14 08:49:54.4654819 write-content kcf9050e1a495f80cf85fa1f6bf7637b7 already-exists
2021-02-14 08:49:54.4669210 write-content k3f53378840150b23e48a9f939c6d2250 already-exists
2021-02-14 08:49:54.4710787 write-content kf953c6cd5fb572f1e44b6448f5a7b657 already-exists
2021-02-14 08:49:54.4723600 write-content k14f045a5c47a34506faeaac5e60d0aad already-exists
2021-02-14 08:49:54.4765498 write-content k6e29076034b84aa4f177558fa31d68d5 already-exists
2021-02-14 08:49:54.4776646 write-content kbaa458ad84429e60bd0554f77bfb1aa5 already-exists
2021-02-14 08:49:54.4817803 write-content k608f956ed39a7b64b1eaf0d7a2128dfa already-exists
2021-02-14 08:49:54.4829574 write-content kd2b09fb240e75dddc552ef97770d76b6 already-exists
2021-02-14 08:49:54.4873080 write-content k65dcf0fde90b5821419a87c508e54aad already-exists
2021-02-14 08:49:54.4884438 write-content k3a2ba78a0f6c6ecb77b6236bf8041e8c already-exists
2021-02-14 08:49:54.4924668 write-content kee8ecd3e3c3e5e6403061f53d9b99b19 already-exists
2021-02-14 08:49:54.4938217 write-content kdd3352d79becad6480bd7095a927a418 already-exists
2021-02-14 08:49:54.4977596 write-content k53b32218aaeedc420633bca5b35d389b already-exists
2021-02-14 08:49:54.4988321 write-content k7fca2a14c43bbb62de21bd89a119cde8 already-exists
2021-02-14 08:49:54.5027937 write-content k1fb7ae2ed93ff68266176115d51eec06 already-exists
2021-02-14 08:49:54.5039073 write-content kc2a036b3c2f76fe7c03aa993e80afb30 already-exists
2021-02-14 08:49:54.5081874 write-content k6b3377e832cbd743d3fe0c0bb2b87206 already-exists
2021-02-14 08:49:54.5092965 write-content k71a292d19aa37305544c22d795b8ee34 already-exists
2021-02-14 08:49:54.5139047 write-content k63c536413cff9bc354eb8735f40274b4 already-exists
2021-02-14 08:49:54.5150647 write-content kb100d54a9f271bd43b29c90bc65eb8fc already-exists
2021-02-14 08:49:54.5195656 write-content kb3ac292f3b0dfbb299edcc50c3ec7fe1 already-exists
6

It actually went a bit further, but gave up eventually. I have now decided to re-create this repo from scratch, but I’d welcome some pointers on how to approch this, should this happen again.

7

Please don’t. Let’s understand what’s going on. Can you hop on slack so we can investigate interactively?

8

Ehh… too late… sorry, but I really wanted to get my server repo back up and running. I promise, that I will do better next time, though.

9

This is telling me that the client keeps sending content that was already backed up. This is generally a no-op server side but will send potentially a bunch of data over the wire. I think probably waiting enough time would have completed the snapshot.

10

Well… at least KopiaUI seems to disagree, since at one time, the operation got aborted and KopiaUI showed a 0 Byte snapshot. I will hold m horses the next time and we might be able to get down to the root cause then.

Since this wasn’t the first snaptshot, I’d assume that most of the content was already in the repo. This repo has been in use for a couple of weeks without any issue up to a couple of days ago.

11

I found a possible performance improvement for this case. We can avoid uploading the content and deduplicating it server-side if the client can locally hash the data and check that the server already has it, thus avoiding 20MB+ uploads.

12

Oh well… I actually thought, that the client would do that already. However, even if a content blob would need re-uplaoding, it shoudln’t kill the snapshot in the end, should it?

I am still clueless as of why this happened in the first place and it seems, that I am still getting these error, despite the fact, that I re-created the repo. So, we might be still able to take a closer look at the kopia server. If this helps… I also got there error this night, when my Mac was performing the initial snapshot…

3 Errors During Snapshot
Path: Pictures/Fotos Library.photoslibrary/originals/7/7362292D-7838-4FBB-BF31-8BCB3CDC339C.jpeg
Error: Put "https://10.10.0.252:5151/api/v1/contents/a54554941a6392cba6822a8de6b8a239": read tcp 10.10.0.106:50428->10.10.0.252:5151: read: connection reset by peer
Path: Pictures/iPhone/IMG_2087.MOV
Error: Put "https://10.10.0.252:5151/api/v1/contents/177d4bf5920ea40bf3f6aec3780f0178": remote error: tls: bad record MAC
Path: nextcloudBudy/Billes Photos/2016/04/2016-04-30 15-29-14 1269.jpg
Error: Put "https://10.10.0.252:5151/api/v1/contents/7743bb10e485ac27a2fe9110351dccf4": remote error: tls: bad record MAC
13

Suggests that some network issue may be at fault and disabling checksum offloading fixes the problem.

I will be available to debug this in couple more hours. Ping me on slack if you can.

14

You mean, disable checksum off-loading on the client or on the server? From the quoted issue on github, I assume, that it should be done on the client. So on macOS, the only thing I can come up with is:

sudo sysctl -w net.inet.tcp.tso=0

I will check, if that helps when I am home… However, this would be likely a serious issue for all Mac Users, since the update to 11.2 already removed all of my former tweaks in /etc/sysctl.conf…

15

I honestly don’t know. Will upgrade my Mac to 11.2 and will see.

16

Soo… I had the chance to take a lool at the cli-log while KopiaUI had been stalling for a long time and I found out, that it was churning at the Apple Mail V8 folder - which I also got new, when I updated to 11.2. I am usually not a Apple Mail person, so this either would have or would have not been an issue before, but as I said, I am simply not using Apple Mail - I only had it configured for testing purposes.

I disabled, removed and cleaned up Apple Mail’s remnants and tried once more - issue gone.

Just that you can get glimpse… my modest mailbox was 1.4GB in size, but it contained a lot of very small files:

stephan@stephan V8 % ls -lR | wc -l
  128945