Prune Fails: GCD_RETRY: The user does not have sufficient permissions for this file

saspus · 9 July 2021 06:11

Ok, I ran it again and got the same original error:

2021-07-08 21:38:33.743 TRACE CHUNK_FOSSILIZE The chunk 5708800574be091362a8f7f54155cadf3c646fa7ab3092fd7697815137ad5e3e has been marked as a fossil
2021-07-08 21:38:34.321 WARN CHUNK_FOSSILIZE Chunk c8be6e7355aea991931d5228464dd445386af742a6d90b1c652c91b0d7dea96a is already a fossil
2021-07-08 21:38:34.462 INFO FOSSIL_COLLECT Fossil collection 1 saved
2021-07-08 21:38:35.290 DEBUG GCD_RETRY [0] The user does not have sufficient permissions for this file.; retrying after 2.32 seconds (backoff: 2, attempts: 1)
2021-07-08 21:38:38.229 DEBUG GCD_RETRY [0] The user does not have sufficient permissions for this file.; retrying after 2.07 seconds (backoff: 4, attempts: 2)
2021-07-08 21:38:40.790 DEBUG GCD_RETRY [0] The user does not have sufficient permissions for this file.; retrying after 14.87 seconds (backoff: 8, attempts: 3)
2021-07-08 21:38:56.265 DEBUG GCD_RETRY [0] The user does not have sufficient permissions for this file.; retrying after 16.40 seconds (backoff: 16, attempts: 4)

I’m going to run with dry run and see what does it try to do at this point.

Edit. It has been a few hours and it progressed past the point it failed before.

2021-07-09 00:13:22.645 WARN CHUNK_FOSSILIZE Chunk c8be6e7355aea991931d5228464dd445386af742a6d90b1c652c91b0d7dea96a is already a fossil
2021-07-09 00:13:23.261 WARN CHUNK_FOSSILIZE Chunk b62d72d11bafc5a5a67bb4857c18358558e452c6486c71bf057449b3d2b17d18 is already a fossil
2021-07-09 00:13:24.867 WARN CHUNK_FOSSILIZE Chunk 9d9801ab2a63580597e496baf227b072a6770c4b6c4abfd9ad7e7e508975bf5b is already a fossil
2021-07-09 00:13:26.292 WARN CHUNK_FOSSILIZE Chunk 968bc7ec83b2e255e081559e134aba77c07cf0e50102b0c3639ffa06d57df6f0 is already a fossil
...

Could it be intermittent issues at google? Or it could be that now there are more stuff to fossilize as it’s a new day. Watching it progress…

saspus · 10 July 2021 02:15

After some more experimenting (see full logs here if interested https://1drv.ms/u/s!ArUmnWK8FkGnkvhVY_zPz802KgFqOg?e=wV6tMw) it looks like it was failing to SNAPSHOT_DELETE.

I created another storage which points directly to the google account that created the shared folder, as opposed to the account that shared folder was shared with, and the prune completed successfully.

2021-07-09 19:04:58.585 WARN CHUNK_FOSSILIZE Chunk 6ca17f466d2fa26e4e3b53c938adac0a38a6b60fe981833fa673b2170e8c21dc is already a fossil
2021-07-09 19:04:59.273 WARN CHUNK_FOSSILIZE Chunk 7844ba28a9aa46a1642c030b95c58259c37c82641aa6bdd6565083d226107d7c is already a fossil
2021-07-09 19:04:59.944 WARN CHUNK_FOSSILIZE Chunk e23dae6f5358746cabf3fc93aa8e9245b0f0f060b1affe1c8c912c2dd0aff2db is already a fossil
2021-07-09 19:05:00.617 WARN CHUNK_FOSSILIZE Chunk 273efbfe18c7b1eee64735417405be70646ad96adea7413f3b8222546b6c559d is already a fossil
2021-07-09 19:05:00.734 INFO FOSSIL_COLLECT Fossil collection 1 saved
2021-07-09 19:05:01.934 INFO SNAPSHOT_DELETE The snapshot obsidian-users at revision 4 has been removed
2021-07-09 19:05:03.067 INFO SNAPSHOT_DELETE The snapshot obsidian-users at revision 5 has been removed
2021-07-09 19:05:04.323 INFO SNAPSHOT_DELETE The snapshot obsidian-users at revision 6 has been removed
2021-07-09 19:05:05.617 INFO SNAPSHOT_DELETE The snapshot obsidian-users at revision 7 has been removed
2021-07-09 19:05:06.869 INFO SNAPSHOT_DELETE The snapshot obsidian-users at revision 8 has been removed
2021-07-09 19:05:08.077 INFO SNAPSHOT_DELETE The snapshot obsidian-users at revision 9 has been removed
...

Any idea why that could be the case? I confirmed that the snapshot files can be deleted by CyberDuck using the other google account: maybe there is some issue with duplicacy doing things differently deleting the stuff via shared account?

For now as a workaround I can just use the connection to main account to do prune, but it would be great to get to the bottom of this.

saspus · 10 July 2021 03:02

Oh, and as a separate discussion: i think retrying on genuine permission issues makes no sense: instead, duplicacy should skip the problematic file and continue.

gchen · 12 July 2021 03:28

This looks like the exact bug in Prune failure on Google team drives.

The code to remove a file in Google Drive is pretty straightforward and I don’t know what can go wrong. If this happens again I can send you a small go program that can only delete a file using the standard Google Drive api (which is what Duplicacy does) to see if it reports any error.

saspus · 12 July 2021 04:23

Indeed it does. Not sure why I did not find that topic; but the issue wasn’t resolved there either anyway.

For me it is 100% reproducible, when using the other account, that the shared drive is shared with.

I have weekly prune schedule on Sunday night – so here is the log from today (in its entirety; it’s smaller because I pruned using the main account yesterday and there are fewer revisions to delete)

Running prune command from /Library/Caches/Duplicacy/localhost/all
Options: [-log prune -storage Rabbit -keep 0:1800 -keep 7:30 -keep 1:7 -a]
2021-07-11 00:20:41.928 INFO STORAGE_SET Storage set to gcd://Backups@Duplicacy
2021-07-11 00:20:45.106 INFO RETENTION_POLICY Keep no snapshots older than 1800 days
2021-07-11 00:20:45.106 INFO RETENTION_POLICY Keep 1 snapshot every 7 day(s) if older than 30 day(s)
2021-07-11 00:20:45.106 INFO RETENTION_POLICY Keep 1 snapshot every 1 day(s) if older than 7 day(s)
2021-07-11 00:21:11.915 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 65
2021-07-11 00:21:12.598 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 66
2021-07-11 00:21:13.246 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 67
2021-07-11 00:21:13.883 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 69
2021-07-11 00:21:14.491 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 70
2021-07-11 00:21:15.097 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 71
2021-07-11 00:21:15.712 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 72
2021-07-11 00:21:16.317 INFO SNAPSHOT_DELETE Deleting snapshot obsidian-users at revision 73
2021-07-11 01:07:25.190 INFO FOSSIL_COLLECT Fossil collection 1 saved
2021-07-11 01:21:05.834 INFO GCD_RETRY [0] Maximum number of retries reached (backoff: 64, attempts: 15)
2021-07-11 01:21:05.834 ERROR SNAPSHOT_DELETE Failed to delete the snapshot obsidian-users at revision 65: googleapi: Error 403: The user does not have sufficient permissions for this file., insufficientFilePermissions
Failed to delete the snapshot obsidian-users at revision 65: googleapi: Error 403: The user does not have sufficient permissions for this file., insufficientFilePermissions

Lets try the small proof-of-concept app.

gchen · 14 July 2021 04:11

Here is a program that can delete a given file. You’ll need to compile it first and then provide a token file as well as the file to delete:

go build gcd_delete.go
./gcd_delete <token file> <file to delete>

package main

import (
	"encoding/json"
	"fmt"
	"io/ioutil"
	"log"
	"os"
	"strings"

	"golang.org/x/net/context"
	"golang.org/x/oauth2"
	"golang.org/x/oauth2/google"
	"google.golang.org/api/drive/v3"

	"google.golang.org/api/option"
)

type GCDConfig struct {
	ClientID     string          `json:"client_id"`
	ClientSecret string          `json:"client_secret"`
	Endpoint     oauth2.Endpoint `json:"end_point"`
	Token        oauth2.Token    `json:"token"`
}

func getInfo(service *drive.Service, parent string, name string) (exist bool, fileID string) {
	query := "name = '" + name + "' and '" + parent + "' in parents and trashed != true"
	if parent == "" {
		query = "name = '" + name + "' and ('root' in parents or sharedWithMe) and trashed != true"
	}
	fileList, err := service.Files.List().Q(query).Fields("files(name, mimeType, id, size)").Do()
	if err != nil {
		fmt.Printf("Fail to check %s: %v\n", name, err)
		return false, ""
	}

	if len(fileList.Files) == 0 {
		return false, ""
	}

	if len(fileList.Files) > 1 {
		fmt.Printf("More than one file named '%s' exists\n", name)
		for _, file := range fileList.Files {
			fmt.Printf("%s %s %s %d\n", file.Name, file.MimeType, file.Id, file.Size)
		}
	}

	return true, fileList.Files[0].Id
}

func main() {
	ctx := context.Background()

	description, err := ioutil.ReadFile(os.Args[1])
	if err != nil {
		log.Fatalf("Unable to read the token file: %v", err)
		return
	}

	var object map[string]interface{}

	err = json.Unmarshal(description, &object)
	if err != nil {
		log.Fatalf("Failed to parse the token file: %v", err)
		return
	}

	isServiceAccount := false
	if value, ok := object["type"]; ok {
		if authType, ok := value.(string); ok && authType == "service_account" {
			isServiceAccount = true
		}
	}

	var tokenSource oauth2.TokenSource

	scope := drive.DriveScope

	if isServiceAccount {
		if newScope, ok := object["scope"]; ok {
			scope = newScope.(string)
		}
		config, err := google.JWTConfigFromJSON(description, scope)
		if err != nil {
			log.Fatalf("Failed to create the oauth config: %v", err)
			return
		}
		if subject, ok := object["subject"]; ok {
			config.Subject = subject.(string)
		}
		tokenSource = config.TokenSource(ctx)
	} else {
		gcdConfig := &GCDConfig{}
		if err := json.Unmarshal(description, gcdConfig); err != nil {
			log.Fatalf("Failed to create the oauth config: %v", err)
			return
		}

		config := oauth2.Config{
			ClientID:     gcdConfig.ClientID,
			ClientSecret: gcdConfig.ClientSecret,
			Endpoint:     gcdConfig.Endpoint,
		}
		tokenSource = config.TokenSource(ctx, &gcdConfig.Token)
	}

	service, err := drive.NewService(ctx, option.WithTokenSource(tokenSource))
	if err != nil {
		log.Fatalf("Unable to create drive Client %v", err)
		return
	}

	filePath := os.Args[2]
	names := strings.Split(filePath, "/")
	parentID := ""
	for _, name := range names {
		exist, fileID := getInfo(service, parentID, name)
		if !exist {
		        log.Fatalf("%s doesn't exist", filePath)
			return
		}
		parentID = fileID
	}

	log.Printf("%s: %s", filePath, parentID)
	err = service.Files.Delete(parentID).SupportsAllDrives(true).Fields("id").Do()
	if err != nil {
		log.Fatalf("Failed to delete %s: %v", filePath, err)
	} else {
		log.Printf("%s has been successfully deleted", filePath)
	}

}

saspus · 15 July 2021 05:35

How would I specify path to a file that resides on shared drive?

e.g. Shared drives/Backups/test1.txt ?

I seemingly tried al combinations:

% ./gcd_delete ./gcd-token-full-access.json "Shared drives/Backups/test1.txt"
2021/07/14 22:33:49 Shared drives/Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "/Shared drives/Backups/test1.txt"
2021/07/14 22:33:56 /Shared drives/Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "Backups/test1.txt"
2021/07/14 22:34:04 Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "/Shared drives/Backups/test1.txt"
2021/07/14 22:34:21 /Shared drives/Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "/Backups/test1.txt"
2021/07/14 22:34:37 /Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "Backups/test1.txt"
2021/07/14 22:36:08 Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "test1.txt"
2021/07/14 22:38:35 test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "//Backups/test1.txt"
2021/07/14 22:39:30 //Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "/Backups/test1.txt"
2021/07/14 22:39:35 /Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "/Shared Drives/Backups/test1.txt"
2021/07/14 22:39:43 /Shared Drives/Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "Backups/test1.txt"
2021/07/14 22:41:35 Backups/test1.txt doesn't exist
% ./gcd_delete ./gcd-token-full-access.json "/Backups/test1.txt"
2021/07/14 22:41:39 /Backups/test1.txt doesn't exist

Droolio · 15 July 2021 14:11

Out of curiosity, couldn’t Rclone help with deleting this stubborn file?

saspus · 15 July 2021 18:04

It seems duplicacy cannot delete the snapshot files and only when accessed via shared account; CyberDuck and Transmit have no issues deleting those files; I haven’t tried with rclone. I will try, using the same duplicacy token, that’s a good idea.

gchen · 16 July 2021 04:04

If you change this line:

		query = "name = '" + name + "' and ('root' in parents or sharedWithMe) and trashed != true"

to:

		query = "name = '" + name + "' and ('drive_id' in parents or sharedWithMe) and trashed != true"

It should be able to find files in the shared drive. The id of the shared drive should be the last component in the url when you open the shared drive in a browser.

saspus · 16 July 2021 23:16

So, this is what the URL looks like:

I replace ‘root’ with ‘0AEl_WsV3iBEbUk9PVA’ and then try to delete the file test1.txt which resides directly there:

% vim gcd_delete.go
% ag 'parents or sharedWithMe'
gcd_delete.go
29:		query = "name = '" + name + "' and ('0AEl_WsV3iBEbUk9PVA' in parents or sharedWithMe) and trashed != true"
% GO111MODULE="off" go build gcd_delete.go
% ./gcd_delete ./gcd-token-full-access.json 'test1.txt'
2021/07/16 16:12:18 test1.txt doesn't exist

I’m probably doing something silly here…

gchen · 17 July 2021 03:37

My bad. The drive id isn’t specified that way. You’ll need to add a few API calls such as this:

	query := "name = '" + name + "' and '" + parent + "' in parents and trashed != true"
	if parent == "" {
		query = "name = '" + name + "' and ('root' in parents or sharedWithMe) and trashed != true"
	}
    query = query.DriveId('0AEl_WsV3iBEbUk9PVA').IncludeItemsFromAllDrives(true).Corpora("drive").SupportsAllDrives(true)

saspus · 18 July 2021 04:50

Not sure what you mean here. DriveID is not a member of string of course, calling that on Q did not work either…

gchen · 18 July 2021 15:58

Sorry I just copied that line from Duplicacy’s source code not realizing that variables are different.

This has been tested to work:

        query := "name = '" + name + "' and '" + parent + "' in parents and trashed != true"
        if parent == "" {
                query = "name = '" + name + "' and ('0AEl_WsV3iBEbUk9PVA' in parents or sharedWithMe) and trashed != true"
        }
        fileList, err := service.Files.List().Q(query).Fields("files(name, mimeType, id, size)").DriveId("0AEl_WsV3iBEbUk9PVA").IncludeItemsFromAllDrives(true).Corpora("drive").SupportsAllDrives(true).Do()

The last fix to make it work is to change 'root' in parents to 'drive_id' in parents.

saspus · 19 July 2021 04:24

Bingo!

% ./gcd_delete ./gcd-token-duplicacy-arrogant-full-access.json 'test1.txt'
2021/07/18 21:15:15 test1.txt: 1_GpYzHvj608U7OqKg0wUzuJjb1DAi491
2021/07/18 21:15:16 test1.txt has been successfully deleted

% ./gcd_delete ./gcd-token-duplicacy-saspus-shared-access.json 'test2.txt'
2021/07/18 21:15:34 test2.txt: 1l8ACiJHfnuMowm-4g58wDF2munddPkmk
2021/07/18 21:15:34 Failed to delete test2.txt: googleapi: Error 403: The user does not have sufficient permissions for this file., insufficientFilePermissions

Now, both test1 and test2 are created by user x@arrogantrabbit.com and the shared folder is shared to user x@saspus.com, as a content manager, which is supposed to have delete permissions, according to the screenshot

Why can’t we delete file then?

Edit. As a matter of testing, I switched the sharing to Manager (as opposed to “Content Manager”) and deletion succeeded:

% ./gcd_delete ./gcd-token-duplicacy-saspus-shared-access.json 'test2.txt'
2021/07/18 21:27:29 test2.txt: 1l8ACiJHfnuMowm-4g58wDF2munddPkmk
2021/07/18 21:27:29 test2.txt has been successfully deleted

Then I uploaded a file again, changed the sharing mode to Content Manager again, and it failed again:

% ./gcd_delete ./gcd-token-duplicacy-saspus-shared-access.json 'test2.txt'
2021/07/18 21:28:39 test2.txt: 1Zu6PBhDtlOEFVzo39o8ZvQ59_pNIWp_H
2021/07/18 21:28:40 Failed to delete test2.txt: googleapi: Error 403: The user does not have sufficient permissions for this file., insufficientFilePermissions

So, is this is google bug? Content Manager is supposed to be able to delete files, or it is duplicacy/test app/go google module issue by perhaps requesting too wide permissions to perform delete? (logging in to drive.google.com with x@saspus.com account allows to delete the file in both cases, so the google permissions seem to work correctly; it has to be some programmatic issue on the app or library side)

Edit. And lastly, perhaps when pruning duplicity should delete snapshots first, and chunks last: otherwise my datastore is now in a bit bad shape – the chunks were deleted, but snapshots not, and now check fails due to those ghost snapshots. This could also happen if the prune is interrupted. The idea being that it’s better to leave extra chunks behind than end up with a visible snapshot referencing missing chunks.

Droolio · 19 July 2021 16:43

I’ve run into this issue a few times before, where I came to realise the reason for oodles of missing chunks was due to the prune job not properly finishing due to one reason or another.

I can’t quite remember exactly, but I think this caused a cascading issue where the next prune was trying to remove yet more snapshots, but aborted due to not finding expected chunks to delete. And then even more chunks were removed from storage.

Perhaps Duplicacy should rename the snapshot file to e.g 1.del first, delete chunks, then delete the marked snapshots? (I realise it doesn’t help to have *.del files left around, since they’re technically unusable, but they’d be an indication that something went wrong and that the storage may need a cleanup via -exhaustive).

gchen · 21 July 2021 05:02

Did you mean that you can assign the user account as a Manager instead of a Content manager of the shared drive to fix the issue?

Was there a difference in creating test1.txt and test2.txt that caused them to behave differently when deleted?

Snapshots are deleted in the fossil collection step while the chunks are deleted in the fossil deletion step. If some snapshots are deleted and other are not (due to interruption or failures) then all chunks are still there but in the form of fossils.

If snapshots are deleted first then you may end up with lots of unreferenced chunks which can be only fixed by prune with -exhaustive.

saspus · 21 July 2021 05:51

Correct. Both the test app and duplicacy prune succeeds.

No difference, both uploaded from a local disk via browser to main account. The difference was different json token file provided — attempting to delete test1 using connection to main account and test2 using connection to second account. There is no other reason, I could use the same file.

The main takeaway here is as you said above — when sharing as Manager deletion via app works, but when sharing as content manager —does not. Deletion via google web app works in both cases, so something must be with the app/framework/public api.

saspus · 21 July 2021 05:53

I understand that; it’s just I feel this arguably is preferable to a scary message that check failed.

Not a big deal really.

Droolio · 21 July 2021 13:53

This doesn’t apply to local file system (and SSH?) storage backends am I correct? On this tangent, would it be a good idea to ‘fossilise’ snapshot files when deleting chunks? To make sure an interrupted or failed prune doesn’t leave bad snapshots around.