Duplicacy thinks the chunk does not exist, and yet, it does

Support
#1

The prune on the google drive (configured via gcd_start) failed, with no other diagnostic:

2021-11-04 01:21:17.530 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1613
2021-11-04 01:21:18.652 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1614
2021-11-04 01:21:19.692 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1615
2021-11-04 01:21:20.784 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1616
2021-11-04 01:21:21.946 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 1617
2021-11-04 01:38:51.853 ERROR CHUNK_FIND Chunk 6d027b343cb29645d7c5dfc7d50632d1006bde419c61dbf83394818417f20c9b does not exist in the storage
Chunk 6d027b343cb29645d7c5dfc7d50632d1006bde419c61dbf83394818417f20c9b does not exist in the storage

Mounting the storage with rclone I see that chunk is actually present:

image
image1650×186 55.4 KB

If that was google API failure – there should be error log. Does it mean this is google bug or there is some unhandled failure path in Google Drive API library and/or duplicacy?

Update. I ran it again, with -d, and it worked correctly this time:

2021-11-04 12:00:00.734 TRACE CHUNK_FOSSILIZE The chunk 6d027b343cb29645d7c5dfc7d50632d1006bde419c61dbf83394818417f20c9b has been marked as a fossil

So it is indeed some intermittent failure of the backend that duplicacy does not check for (either itself, or in the library)

Update2: and while it was running – backup failed:

Running backup command from /Library/Caches/Duplicacy/localhost/0 to back up /Users
Options: [-log backup -storage Rabbit -vss -stats]
2021-11-04 13:00:01.976 INFO REPOSITORY_SET Repository set to /Users
2021-11-04 13:00:01.976 INFO STORAGE_SET Storage set to gcd://Duplicacy
2021-11-04 13:00:05.581 INFO BACKUP_KEY RSA encryption is enabled
2021-11-04 13:00:05.581 INFO BACKUP_EXCLUDE Exclude files with no-backup attributes
2021-11-04 13:00:06.988 ERROR SNAPSHOT_NOT_EXIST Snapshot obsidian-users at revision 1670 does not exist
Snapshot obsidian-users at revision 1670 does not exist
#2

This means when Duplicacy listed the directory snapshot/obsidian-users, revision 1670 was included in the returned list (as the last one). But when it tried to download this file Google Drive said this file didn’t exist.

Do you see this file in Google Drive?

#3

It was missing. Not sure why was it present in the enumeration / or why did it disappear later. This is the very last snapshots, so it would not be affected by the prune.

Do you have any ideas what could have happened with the first issue – missing chunk that wasn’t missing?

Edit. I take that back. The file re-appeared now:

image
image1708×330 21.7 KB

Apparently it was created 12:15PM, and the log message about it missing was printed 13:00PM. So, it must have existed, it was correctly enumerated in list, and then disappeared for a short time!? I have no idea what’s going on there.

Maybe these two issues are related – some synchronization issues at google?

#4

Probably not related to your issue, just thought worth mentioning…

Recently I’ve been playing around with Google Docs on G Suite, and noticed that the web view sometimes isn’t as ‘live’ as you might expect. Forcing a refresh (Ctrl-F5) often resolves it.

Could recent change in daylight savings account for the timestamps?

#5

Thank you.

I was opening google drive in a new browser tab every time (I don’t keep it open). I did not check what rclone remote saw at that time though…

Great idea with DST. To verify I just did touch 6_03_PM in rclone mount, then touched 6_05_pm_dragged outside of mount, went to the drive interface, and dragged that second file into there via browser.

image
image1096×202 5.3 KB

It seems the time is handled correctly both times.

#6

Now backup kept failing all the time like so, until I deleted the cache:

Running backup command from /Library/Caches/Duplicacy/localhost/0 to back up /Users
Options: [-log backup -storage Rabbit -vss -stats]
2021-11-04 23:43:04.975 INFO REPOSITORY_SET Repository set to /Users
2021-11-04 23:43:04.975 INFO STORAGE_SET Storage set to gcd://Duplicacy
2021-11-04 23:43:08.255 INFO BACKUP_KEY RSA encryption is enabled
2021-11-04 23:43:08.255 INFO BACKUP_EXCLUDE Exclude files with no-backup attributes
2021-11-04 23:43:10.833 ERROR SNAPSHOT_NOT_EXIST Snapshot obsidian-users at revision 1671 does not exist
Snapshot obsidian-users at revision 1671 does not exist

1671 did not exist on storage.

This corner case needs to get addressed – if state of storage does not match state of cache – the cache should be discarded.

Edit. Deleting cache allowed it progress further, until it failed to download another existing chunk again:

Running backup command from /Library/Caches/Duplicacy/localhost/0 to back up /Users
Options: [-log backup -storage Rabbit -vss -stats]
2021-11-04 23:44:09.362 INFO REPOSITORY_SET Repository set to /Users
2021-11-04 23:44:09.362 INFO STORAGE_SET Storage set to gcd://Duplicacy
2021-11-04 23:44:12.719 INFO BACKUP_KEY RSA encryption is enabled
2021-11-04 23:44:12.720 INFO BACKUP_EXCLUDE Exclude files with no-backup attributes
2021-11-04 23:52:16.608 ERROR DOWNLOAD_CHUNK Chunk 4946b135cc220eae1b3585e5b79262e7ae53c412dd68d3b526b26e7a067f1f17 can't be found
Chunk 4946b135cc220eae1b3585e5b79262e7ae53c412dd68d3b526b26e7a067f1f17 can't be found

and yet:

% rclone ls google-drive-exclusive:/Duplicacy/chunks/49 | grep 46b135cc220eae1b3585e5b79262e7ae53c412dd68d3b526b26e7a067f1f17
  2902566 46b135cc220eae1b3585e5b79262e7ae53c412dd68d3b526b26e7a067f1f17

And then:

2021-11-05 00:42:50.411 ERROR DOWNLOAD_CHUNK Failed to download the chunk 39f9232d6eb5c8df4b5c79a788bb56df608eed53b466ac04a6f6bbcdfe690571: chunks/39/f9232d6eb5c8df4b5c79a788bb56df608eed53b466ac04a6f6bbcdfe690571 does not exist
Failed to download the chunk 39f9232d6eb5c8df4b5c79a788bb56df608eed53b466ac04a6f6bbcdfe690571: chunks/39/f9232d6eb5c8df4b5c79a788bb56df608eed53b466ac04a6f6bbcdfe690571 does not exist

while

% rclone ls google-drive-exclusive:/Duplicacy/chunks/39 |grep f9232d6eb5c8df4b5c79a788bb56df608eed53b466ac04a6f6bbcdfe690571
 10798374 f9232d6eb5c8df4b5c79a788bb56df608eed53b466ac04a6f6bbcdfe690571

Rclone remote uses credentials from my own google project

@gchen, do you see any issues on the duplicacy google project side? Maybe something with api quotas? anything? The client id is 243147021227-fsjl96dn4h39ohcrrit1nb5tascroe6n.apps.googleusercontent.com. it has to be something with the service.

#7

Duplicacy reads the local copy in the cache only after it finds the file in the storage. It doesn’t list the snapshots directory in the cache.

I guess it went further on second try not because you deleted the cache, but because the issue was transient. Maybe it was related to the consistency issue.

It was a different chunk so this means the first one (4946b1…) was correctly downloaded when you tried again. You can confirm this by checking if 4946b1 exists in the local cache. If so then this is similar to the issue of revision 1671 being missing.

#8

It is not in cache:

sh-3.2# find /Library/Caches/Duplicacy/localhost/0/.duplicacy/cache | grep 4946b1
sh-3.2#

Probably deleting the cache caused it to try different chunk first?

It appears the issue has started yesterday noon, and repeated around midnight: top line is hourly backup, bottom – daily prune and check.

image
image2182×274 26.9 KB

Last backup completed successfully without me doing anything.

My concern is that the issue is perhaps related to the shared google project limits in some way? (because the rclone with custom project seems to be working fine)

#9

You should grep 46b1 instead of 4946b1.

I believe Duplicacy should read metadata chunks of last backup in the same order.

Can you run rclone with the same credential file to download the missing chunk when this happens again?

#10

doh!

But that one is missing as well:

sh-3.2# find /Library/Caches/Duplicacy/localhost/0/.duplicacy/cache | grep 46b1
sh-3.2#

Since this is intermittent, it would be unclear how to reliably do that.
I’ll watch backup for a few more days, and if this issues keeps repeating – I’ll switch duplciacy to using service account with custom project and see if that makes any differnce. If it does – I’ll switch back to web UI to confirm that the original intermittent issue still happens. Only then it woudl be somewhat reliable.

#11

The issue magically disappeared. That’s… annoying.

image
image2174×280 25.5 KB

I’ll watch for a few more days and then I guess we can write it off as temporary google drive hiccups.