Deleting snapshot from google drive fails

Bug
#1

Deleting snapshots from google drive fails silently:

Log:

2021-10-01 19:47:28.726 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1132
2021-10-01 19:47:29.411 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1133
2021-10-01 19:47:30.103 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1134
2021-10-01 19:47:30.762 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1135
2021-10-01 19:47:31.439 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1137
2021-10-01 19:47:32.119 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1138
2021-10-01 19:47:32.781 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1139
2021-10-01 19:47:33.433 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1140
2021-10-01 19:47:34.107 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1141
2021-10-01 19:47:34.860 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1142
2021-10-01 19:47:35.532 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1145
2021-10-01 19:47:36.236 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1147
2021-10-01 19:47:36.920 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1149
2021-10-01 19:47:37.615 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1152
2021-10-01 19:47:40.133 WARN DOWNLOAD_RESURRECT Fossil 228836a3c5e5310d155b48ae5915e5c6bb0771180d6d4c5ff10b0f95c7032ccd has been resurrected
2021-10-01 19:47:42.424 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1153
2021-10-01 19:47:45.444 WARN DOWNLOAD_RESURRECT Fossil 7f45c29b6cf3d79737a92a6c2b21f6b11d67176b98d7c2cb120d851011020a84 has been resurrected

Google Drive view:

image
image1090Ă—1364 56.3 KB

Google drive configured via gcd_start. It’s located in My Drive in Google Workspace account.

Earlier deleting snapshots from shared google drive would fail, but now it seems it fails even when directly connected

Impact: after prune check will fail because the ghost snapshot file is left in the datastore.

Check and prune to continue on failure
#2

The Google Drive api didn’t return any errors (otherwise Duplicacy would have spewed out error messages) so I guess the deletions were successful but weren’t propagated to other servers on time.

I wonder if you wait enough time would those files disappear eventually?

#3

Unfortunately, same files are still there (screenshot with timestamp):

image
image568Ă—1532 57.8 KB

It looks like it silently not deleting those files.

What diagnostic can I provide to help debug this?

#4

Can you pass one of these files to the gcd_delete tool I posted in Prune Fails: GCD_RETRY: The user does not have sufficient permissions for this file - #12 by gchen? Just to see if that tool reports any error.

#5

That seems to work:

% ./gcd_delete_orig ./gcd-token-duplicacy-arrogant-full-access.json Duplicacy/snapshots/obsidian-users/1141
2021/10/03 21:43:09 Duplicacy/snapshots/obsidian-users/1141: 1bK1gWJizj5BozPBb3SmS2247xiNVbtaM
2021/10/03 21:43:09 Duplicacy/snapshots/obsidian-users/1141 has been successfully deleted

and then it is indeed gone, as seen in web app:

image

So duplicacy must be doing that somehow differently - because otherwise it seems like some weird side effect bug somewhere.

#6

I checked the code again and realized that when SNAPSHOT_DELETE logs are displayed, snapshots are not deleted immediately. The API calls to delete these files would happen at a later stage. The failure to download a resurrected chunk as you reported in the other thread aborted the command so these files were never actually deleted.

Therefore, the root cause was that there was a metadata chunk that had already been marked as a fossil, and the prune command found out that this chunk was still needed by a more recent snapshot (which wasn’t seen by the fossil collection step because that backup was likely still in progress at that time).

I think the problem here is that the download procedure should not attempt to resurrect a fossil and then download the resurrected hunk. Instead, it should download the fossil directly and leave the resurrection to the prune command (which will perform a step to resurrect all needed fossils after all required metadata chunks have been downloaded, thus avoiding the read-after-rename consistency issue).

3 Likes
#7

Oh, this is interesting!. If I understand the issue correctly, running check -fossils -resurrect following by prune shall workaround the problem. I’m trying it now (it’s very slow, will take few hours, will report back)

#8

So, the check -fossils -resurrect resurrected a few fossils and then failed like so:

2021-10-06 21:48:47.814 INFO FOSSIL_RESURRECT The chunk chunks/37/887354d270661cc860548ceab02a4cbad50ee3ce73525983abb779d20436cf.fsl has been resurrected
2021-10-06 21:48:50.242 INFO FOSSIL_RESURRECT The chunk chunks/7c/fbb5a59fadded5f59943af10c79b40a6b67a698f76cf27067f5745adf13ece.fsl has been resurrected
2021-10-06 21:48:52.557 INFO FOSSIL_RESURRECT The chunk chunks/f6/c4942c2f77e193102a2964f551d03873cc66cb275d7bc72d2850420fc8a953.fsl has been resurrected
2021-10-06 21:48:52.557 INFO SNAPSHOT_CHECK All chunks referenced by snapshot obsidian-users at revision 1185 exist
2021-10-06 21:48:52.557 DEBUG DOWNLOAD_FETCH Fetching chunk 93eea98f7f5591d78119912a415973b1ff6fa651f0d740daed58cd26ba2a7da2
2021-10-06 21:48:52.561 DEBUG CHUNK_CACHE Chunk 93eea98f7f5591d78119912a415973b1ff6fa651f0d740daed58cd26ba2a7da2 has been loaded from the snapshot cache
2021-10-06 21:48:52.561 DEBUG DOWNLOAD_FETCH Fetching chunk dd306519fb786c9b96362c307c512d727a7cddaeb4b3878b4a27b263c5428e64
2021-10-06 21:48:52.566 DEBUG CHUNK_CACHE Chunk dd306519fb786c9b96362c307c512d727a7cddaeb4b3878b4a27b263c5428e64 has been loaded from the snapshot cache
2021-10-06 21:48:52.566 DEBUG DOWNLOAD_FETCH Fetching chunk d36161a833287ba72086ddc2d1f68c0cedf972b5a85259664c80f53dd8e15b26
2021-10-06 21:48:52.569 DEBUG CHUNK_CACHE Chunk d36161a833287ba72086ddc2d1f68c0cedf972b5a85259664c80f53dd8e15b26 has been loaded from the snapshot cache
2021-10-06 21:48:52.569 DEBUG DOWNLOAD_FETCH Fetching chunk 4657668b0a707020ce7ffa035be66aa5f8297e0abcbfcf4fec7f79bcf3822b3a
2021-10-06 21:48:52.575 DEBUG CHUNK_CACHE Chunk 4657668b0a707020ce7ffa035be66aa5f8297e0abcbfcf4fec7f79bcf3822b3a has been loaded from the snapshot cache
2021-10-06 21:48:52.576 DEBUG DOWNLOAD_FETCH Fetching chunk 7cef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895
2021-10-06 21:48:54.549 WARN DOWNLOAD_RESURRECT Fossil 7cef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895 has been resurrected
2021-10-06 21:48:56.138 WARN DOWNLOAD_RESURRECT Fossil 7cef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895 has been resurrected
[ SAME LINE REPEATED TOTAL 145 times]
2021-10-06 21:52:42.602 WARN DOWNLOAD_RESURRECT Fossil 7cef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895 has been resurrected
2021-10-06 21:52:44.129 WARN DOWNLOAD_RESURRECT Fossil 7cef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895 has been resurrected
2021-10-06 21:52:45.016 ERROR DOWNLOAD_CHUNK Failed to resurrect chunk 7cef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895: The file 'fossils/7c/ef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895' to be moved does not exist
Failed to resurrect chunk 7cef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895: The file 'fossils/7c/ef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895' to be moved does not exist

Looks like that one chunk existed as fossil, so duplicacy decided to resurrect it, and then it disappears? I assume 145 attempts are there to account for the delay the file may take to actually appear post-rename?

in fact, right now ef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895 already exists in chunks folder (and in the local cache)

full log:
check-20211006-183127.log.zip (244.7 KB)

is that perhaps the same bug?

#9

Yes, it is the same bug. It is interesting to see that all fossils before this one were successfully renamed and immediately downloaded without any issue. But for this one, there was a delay that caused the rename operation to repeat 145 times until it failed.

I checked in a new commit which should fix this bug: Download a fossil directly instead of turning it back to a chunk first · gilbertchen/duplicacy@cacf661 · GitHub

#10

Thank you!

It appears that it went past that chunk this time, and no other fail-to-download-after-rename happened.

2021-10-08 12:28:43.634 DEBUG DOWNLOAD_FETCH Fetching chunk 7cef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895
2021-10-08 12:28:46.375 DEBUG CHUNK_DOWNLOAD Chunk 7cef47b5dde9c214bff3af772ff884f0248e964f99cc228a84e0aaeaf3a2a895 has been downloaded
2021-10-08 12:28:47.112 INFO SNAPSHOT_CHECK All chunks referenced by snapshot obsidian-users at revision 1186 exist

But then failed here:

2021-10-08 12:41:16.251 DEBUG DOWNLOAD_FETCH Fetching chunk 50f80ffbf677653e9c9f466a8914ffec614bcdd10123a7bb249c1111a20fcba5
2021-10-08 12:41:16.267 DEBUG CHUNK_CACHE Chunk 50f80ffbf677653e9c9f466a8914ffec614bcdd10123a7bb249c1111a20fcba5 has been loaded from the snapshot cache
2021-10-08 12:41:16.267 DEBUG DOWNLOAD_FETCH Fetching chunk dd306519fb786c9b96362c307c512d727a7cddaeb4b3878b4a27b263c5428e64
2021-10-08 12:41:16.271 DEBUG CHUNK_CACHE Chunk dd306519fb786c9b96362c307c512d727a7cddaeb4b3878b4a27b263c5428e64 has been loaded from the snapshot cache
2021-10-08 12:41:16.272 DEBUG DOWNLOAD_FETCH Fetching chunk d36161a833287ba72086ddc2d1f68c0cedf972b5a85259664c80f53dd8e15b26
2021-10-08 12:41:16.274 DEBUG CHUNK_CACHE Chunk d36161a833287ba72086ddc2d1f68c0cedf972b5a85259664c80f53dd8e15b26 has been loaded from the snapshot cache
2021-10-08 12:41:16.275 DEBUG DOWNLOAD_FETCH Fetching chunk 4657668b0a707020ce7ffa035be66aa5f8297e0abcbfcf4fec7f79bcf3822b3a
2021-10-08 12:41:16.281 DEBUG CHUNK_CACHE Chunk 4657668b0a707020ce7ffa035be66aa5f8297e0abcbfcf4fec7f79bcf3822b3a has been loaded from the snapshot cache
2021-10-08 12:41:16.282 DEBUG DOWNLOAD_FETCH Fetching chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772
2021-10-08 12:41:16.916 WARN DOWNLOAD_FOSSIL Chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772 is a fossil
2021-10-08 12:41:17.193 ERROR DOWNLOAD_CHUNK Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist
Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist

Prune reported the same:

2021-10-08 12:44:21.790 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1192
2021-10-08 12:44:23.010 WARN DOWNLOAD_FOSSIL Chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772 is a fossil
2021-10-08 12:44:23.291 ERROR DOWNLOAD_CHUNK Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist
Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist

The chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist in the chunks/02/ (and moreover none of files there have fsl extension) nor in fossils folder, so it seems it is genuinely missing and snapshot 1192 is one of those that failed to delete pointing to missing chunks.

I’ll delete them from snapshots folder one by one (hoping there won’t be to many of them; since prune stops after encountering an error it will be a long process, until this is fixed: Check and prune to continue on failure)

#11

INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1018

So what prevents duplicacy from deleting the actual snapshot file right when it decided to do so? Why postpone to a later stage? What would be the drawback of doing so immediately? It will eliminate this whole class of issues when half of the chunks are already gone but duplicate was interrupted before it actually deleted half-dead snapshot. Worst case – there will be orphaned chunks, but this won’ cause check or restore failure and can be cleaned up later.

Also, does is status of this still “implemented” given the new insight?

#12

Snapshot deletion can’t be undone, but chunk fossilization can’t, so I still think that snapshot deletion should happen after fossilization.

This is true, but you’ll need the -exhaustive option to search for these chunks. More users will not bother to add this option and these chunks will stay in the storage for a long while.

Did you dig into prune logs to figure out why this chunk is missing?

#13

Fair point. Then duplciacy needs to mark those snapshots in some way so that check failures related to those snapshots will not be fatal anymore (or better yet, skip checking them altogether), and continue cleanup on the next prune invocation. Maybe it is worth introducing the concept of fossil snapshot files?

I might have nuked a tons of longs few weeks ago, as I forgot to remove the -d flag and the folder size got out of hand. I only have this so far, and it’s probably aftermath and not the root cause:

sh-3.2# ag 4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772
duplicacy_web.log
128:2021/10/08 12:41:17 ERROR DOWNLOAD_CHUNK Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist
129:2021/10/08 12:41:17 err: Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist, exitCode: 100
133:2021/10/08 12:44:23 ERROR DOWNLOAD_CHUNK Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist
159:2021/10/08 13:04:29 ERROR DOWNLOAD_CHUNK Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist

prune-20211008-130126.log
1945:2021-10-08 13:04:28.037 DEBUG DOWNLOAD_FETCH Fetching chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772
1946:2021-10-08 13:04:29.391 WARN DOWNLOAD_FOSSIL Chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772 is a fossil
1947:2021-10-08 13:04:29.662 ERROR DOWNLOAD_CHUNK Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist
1948:Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist

check-20211008-113919.log
2543:2021-10-08 12:41:16.282 DEBUG DOWNLOAD_FETCH Fetching chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772
2544:2021-10-08 12:41:16.916 WARN DOWNLOAD_FOSSIL Chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772 is a fossil
2545:2021-10-08 12:41:17.193 ERROR DOWNLOAD_CHUNK Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist
2546:Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist

prune-20211008-124117.log
94:2021-10-08 12:44:23.010 WARN DOWNLOAD_FOSSIL Chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772 is a fossil
95:2021-10-08 12:44:23.291 ERROR DOWNLOAD_CHUNK Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist
96:Failed to download the chunk 024068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772: chunks/02/4068a82de21675cd950c3abfd92189209475fcd1f701f038167adae38cd772.fsl does not exist
Prune fails on message about existing fossil