IO error: googleapi: Error 403: Insufficient Permission, insufficientPermissions

arnoldvilleneuve · August 21, 2019, 4:07pm

IO error: googleapi: Error 403: Insufficient Permission, insufficientPermissions
temp/rclone/rclone-v1.48.0-windows-amd64/rclone.1: File.applyPendingModTime error: googleapi: Error 403: Insufficient Permission, insufficientPermissions
2019/08/20 22:37:14 ERROR : IO error: googleapi: Error 403: Insufficient Permission, insufficientPermissions
2019/08/20 22:37:14 ERROR : temp/rclone_windows.zip: File.applyPendingModTime error: googleapi: Error 403: Insufficient Permission, insufficientPermissions

We are plugging away at rclone for the Google Cloud Platform. I have literally given the SA account we are using full permissions as a Project Owner, Storage Admin, and I even added Org Administrator just to see if the permission errors would go away. Files still get copied over but the log is full of these errors.

Animosity022 · August 21, 2019, 4:16pm

Can you share rclone version and the command you are running with a -vv on it and share the log?

Without more detail, it seems like you have a permissions issue, which I doubt is the case

thestigma · August 21, 2019, 10:24pm

Here are some logs that show the problem. First with -v and then -vv , same order of events. mount, copy a small file, then exit. Tried to keep it short and sweet.

2019/08/22 00:15:57 INFO : Storage bucket rclonestore: poll-interval is not supported by this remote
2019/08/22 00:15:57 INFO : Cleaned the cache: objects 2 (was 0), total size 1024.000M (was 0)
The service rclone has been started.
2019/08/22 00:16:02 INFO :
Transferred: 0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors: 0
Checks: 0 / 0, -
Transferred: 0 / 0, -
Elapsed time: 0s

2019/08/22 00:16:07 INFO :
Transferred: 0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors: 0
Checks: 0 / 0, -
Transferred: 0 / 0, -
Elapsed time: 0s

2019/08/22 00:16:11 INFO : SMALLFILE (10).txt: Copied (new)
2019/08/22 00:16:11 ERROR : SMALLFILE (10).txt: File.applyPendingModTime error: googleapi: Error 403: Insufficient Permission, insufficientPermissions
2019/08/22 00:16:12 INFO :
Transferred: 408 / 408 Bytes, 100%, 1.812 kBytes/s, ETA 0s
Errors: 0
Checks: 0 / 0, -
Transferred: 1 / 1, 100%
Elapsed time: 200ms

The service rclone has been stopped.
Terminate batch job (Y/N)?

Debug log:
https://pastebin.com/Mrp2Kt7B

The same error is in there, but I can't get anything more useful out of it personally. Heres a short selective snippet around the error (near the bottom of the full-size log)

2019/08/22 00:17:18 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2019/08/22 00:17:18 DEBUG : /: >Releasedir: errc=0
2019/08/22 00:17:18 DEBUG : /: >Releasedir: errc=0
2019/08/22 00:17:18 DEBUG : /: >Getattr: errc=0
2019/08/22 00:17:18 DEBUG : /: Releasedir: fh=0x7
2019/08/22 00:17:18 DEBUG : /: >Releasedir: errc=0
2019/08/22 00:17:18 DEBUG : /: Releasedir: fh=0x5
2019/08/22 00:17:18 DEBUG : /: >Releasedir: errc=0
2019/08/22 00:17:18 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2019/08/22 00:17:18 DEBUG : /: >Getattr: errc=0
2019/08/22 00:17:18 DEBUG : /: Opendir:
2019/08/22 00:17:18 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2019/08/22 00:17:18 DEBUG : /: >OpenFile: fd=/ (r), err=
2019/08/22 00:17:18 DEBUG : /: >Opendir: errc=0, fh=0x3
2019/08/22 00:17:18 DEBUG : /: Releasedir: fh=0x3
2019/08/22 00:17:18 DEBUG : /: >Releasedir: errc=0
2019/08/22 00:17:18 ERROR : SMALLFILE (11).txt: File.applyPendingModTime error: googleapi: Error 403: Insufficient Permission, insufficientPermissions
2019/08/22 00:17:18 DEBUG : SMALLFILE (11).txt: transferred to remote
2019/08/22 00:17:18 DEBUG : SMALLFILE (11).txt(0xc0000bc6c0): >close: err=
2019/08/22 00:17:18 DEBUG : /SMALLFILE (11).txt: >Flush: errc=0
2019/08/22 00:17:18 DEBUG : /SMALLFILE (11).txt: Release: fh=0x0
2019/08/22 00:17:18 DEBUG : SMALLFILE (11).txt(0xc0000bc6c0): RWFileHandle.Release nothing to do
2019/08/22 00:17:18 DEBUG : /SMALLFILE (11).txt: >Release: errc=0
2019/08/22 00:17:18 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2019/08/22 00:17:18 DEBUG : /: >Getattr: errc=0
2019/08/22 00:17:18 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2019/08/22 00:17:18 DEBUG : /: >Getattr: errc=0
2019/08/22 00:17:18 DEBUG : /: Opendir:
2019/08/22 00:17:18 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2019/08/22 00:17:18 DEBUG : /: >OpenFile: fd=/ (r), err=
2019/08/22 00:17:18 DEBUG : /: >Opendir: errc=0, fh=0x0
2019/08/22 00:17:18 DEBUG : /: Releasedir: fh=0x0
2019/08/22 00:17:18 DEBUG : /: >Releasedir: errc=0
2019/08/22 00:17:19 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF

If this is actually a simple permissions issue then I don't see what we could be missing.
This is on Google Cloud by the way, not Gdrive.

ncw · August 22, 2019, 12:53pm

Interesting that it was just the applying the pending mod time that caused the problem.

That is should be running a PATCH on the item. Is the account set to items can't be modified?

What happens if you do rclone touch AFILE.txt instead of using the mount?

thestigma · August 22, 2019, 2:04pm

C:\rclone>rclone touch P:\test\afile2.txt -vv
2019/08/22 16:02:09 DEBUG : rclone: Version "v1.48.0-103-g85557827-fix-3330-vfs-beta" starting with parameters ["rclone" "touch" "P:\test\afile2.txt" "-vv"]
2019/08/22 16:02:09 DEBUG : Using config file from "C:\rclone\rclone.conf"
2019/08/22 16:02:09 DEBUG : 3 go routines active
2019/08/22 16:02:09 DEBUG : rclone: Version "v1.48.0-103-g85557827-fix-3330-vfs-beta" finishing with parameters ["rclone" "touch" "P:\test\afile2.txt" "-vv"]

It appears to be only modifying the modtime that fails. I guess there is no need for that part when you create it rather than copy.

I will look through permissions again. I wouldn't be terribly surprised if it's a problem caused by some cryptic policy thing in Gcloud (which I have little familiarity with yet) but it's weird it should be a thing on such a default setup. Unless the Gcloud backend is outdated I doubt it's actually rclone's fault.

thestigma · August 22, 2019, 5:01pm

And here is a -vv --dump bodies as requested:
https://pastebin.com/3FBS9zLJ

SMALLFILE (18).txt is the name of the test-file uploaded so you can search ahead to relevant sections.
Let me know if there is anything else you would like to see.

ncw · August 22, 2019, 9:59pm

Here is the relevant request

2019/08/22 18:57:39 DEBUG : HTTP REQUEST (req 0xc00024c900)
2019/08/22 18:57:39 DEBUG : PATCH /storage/v1/b/rclonestore/o/rclonereadme%20-%20Shortcut.lnk?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-103-g85557827-fix-3330-vfs-beta
Content-Length: 121
Authorization: XXXX
Content-Type: application/json
Accept-Encoding: gzip

{"bucket":"rclonestore","metadata":{"mtime":"1601-01-01T00:59:59.999999900+01:00"},"name":"rclonereadme - Shortcut.lnk"}

and response

2019/08/22 18:57:39 DEBUG : HTTP RESPONSE (req 0xc00024c900)
2019/08/22 18:57:39 DEBUG : HTTP/1.1 403 Forbidden
Content-Length: 160
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Content-Type: application/json; charset=UTF-8
Date: Thu, 22 Aug 2019 16:57:40 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
Www-Authenticate: Bearer realm="https://accounts.google.com/"
X-Guploader-Uploadid: AEnB2UoL9_uhCy0tXkRUu_uMbymP4R623lyK4VsBt8x8C3QYEq3gnItD9UodKcAn1vOOXtq185E99BzQu_FfNRu4ZCG8UTxzbUVqUZsrSmGIKF60bIqufNU

{"error":{"errors":[{"domain":"global","reason":"insufficientPermissions","message":"Insufficient Permission"}],"code":403,"message":"Insufficient Permission"}}

One thing that strikes me as super weird is the time that rclone is trying to set "1601-01-01T00:59:59.999999900+01:00" - From the year 1601????

That is probably the problem..

The wikipedia article on NTFS explains where the 1601 is coming from - it is a zero time value. I probably need to work out where and how to filter that out

Date range: 1 January 1601 – 28 May 60056 (File times are 64-bit numbers counting 100-nanosecond intervals (ten million per second) since 1601, which is 58,000+ years)

You can see these being set in the log, so these times came from Windows via WinFSP

2019/08/22 18:57:39 DEBUG : /rclonereadme - Shortcut.lnk: Utimens: tmsp=[{Sec:-11644473600 Nsec:-100} {Sec:-11644473600 Nsec:-100}]

1970 - 11644473600/365.24/24/3600 = 1600.998795312671

If you do rclone lsl "SMALLFILE (18).txt" on your local machine what do you get?

This must be because of a modtime that isn't set or something like that...

How are you copying the file to the mount? With CP? Can you try different ways, eg with rclone copyto or cp or the windows explorer...

Probably filtering out any times before the 1970 epoch would be the correct thing to do

I made an issue on the cgofuse repo to ask about these times: https://github.com/billziss-gh/cgofuse/issues/35

thestigma · August 22, 2019, 11:28pm

Nice catch - I completely missed that.
Yes, the zero-time is some weird historical artifact. I think this will show for any non-set modtime.
This is actually not the first time I have witnessed files missing modtimes. I have a few of these on my Gdrives too I have noticed - and I think these files were copied via the mount? not 100% sure...

EDIT: the files with "empty" modtimes in windows I have confirmed to be 1601 in rclone lsl, so I guess this is just how windows display the default modtime to prevent confusion.

The modtime in windows of the original file is 05.07.2019 (haven't checked ls because I assume this reads the exact same value). So the file had a normal modtime originally...

The file on the Gcloud reads 22.08.2019 (very certainly the time of upload).

The original copy was done via a simple drag&drop to mount.

Below are various versions of tests - 2 failures and 1 sucess (see last test):

Tested via "rclone copy" to mount P:

C:\rclone>rclone copy "F:\TESTFILES\Stigmatest\SMALLFILES\SMALLFILE (21).txt" P: -vv --dump bodies
2019/08/23 01:06:12 DEBUG : rclone: Version "v1.48.0-103-g85557827-fix-3330-vfs-beta" starting with parameters ["rclone" "copy" "F:\TESTFILES\Stigmatest\SMALLFILES\SMALLFILE (21).txt" "P:" "-vv" "--dump" "bodies"]
2019/08/23 01:06:12 DEBUG : Using config file from "C:\rclone\rclone.conf"
2019/08/23 01:06:12 DEBUG : SMALLFILE (21).txt: Couldn't find file - need to transfer
2019/08/23 01:06:12 INFO : SMALLFILE (21).txt: Copied (new)
2019/08/23 01:06:12 INFO :
Transferred: 408 / 408 Bytes, 100%, 1.136 kBytes/s, ETA 0s
Errors: 0
Checks: 0 / 0, -
Transferred: 1 / 1, 100%
Elapsed time: 300ms

2019/08/23 01:06:12 DEBUG : 3 go routines active
2019/08/23 01:06:12 DEBUG : rclone: Version "v1.48.0-103-g85557827-fix-3330-vfs-beta" finishing with parameters ["rclone" "copy" "F:\TESTFILES\Stigmatest\SMALLFILES\SMALLFILE (21).txt" "P:" "-vv" "--dump" "bodies"]

Result: file on Gcloud still has the upload time as it's modtime (same problem).

Tested windows cmd copy to mount P:

F:\TESTFILES\Stigmatest\SMALLFILES> copy "SMALLFILE (31).txt" P:
1 file(s) copied.

modtime = upload time = same problem.

Tested "rclone copy" directly to remote name

C:\rclone>rclone copy "F:\TESTFILES\Stigmatest\SMALLFILES\SMALLFILE (35).txt" Gcloudtest:rclonestore -vv --dump bodies
2019/08/23 01:19:11 DEBUG : rclone: Version "v1.48.0-103-g85557827-fix-3330-vfs-beta" starting with parameters ["rclone" "copy" "F:\TESTFILES\Stigmatest\SMALLFILES\SMALLFILE (35).txt" "Gcloudtest:rclonestore" "-vv" "--dump" "bodies"]
2019/08/23 01:19:11 DEBUG : Using config file from "C:\rclone\rclone.conf"
2019/08/23 01:19:11 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 01:19:11 DEBUG : HTTP REQUEST (req 0xc0002e8000)
2019/08/23 01:19:11 DEBUG : GET /storage/v1/b/rclonestore/o/SMALLFILE%20%2835%29.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-103-g85557827-fix-3330-vfs-beta
Authorization: XXXX
Accept-Encoding: gzip

2019/08/23 01:19:11 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 01:19:11 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 01:19:11 DEBUG : HTTP RESPONSE (req 0xc0002e8000)
2019/08/23 01:19:11 DEBUG : HTTP/1.1 404 Not Found
Content-Length: 191
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Content-Type: application/json; charset=UTF-8
Date: Thu, 22 Aug 2019 23:19:11 GMT
Expires: Mon, 01 Jan 1990 00:00:00 GMT
Pragma: no-cache
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2UpfVKgnATdfCeHgmaq37jnh0eB0i_v6cIE4xuCsIs-9gCkL1VJpGBRmyJmsNkshCHwN28j6bHZkJvAQWD5DLrsg-RqzXA

{"error":{"code":404,"message":"No such object: rclonestore/SMALLFILE (35).txt","errors":[{"message":"No such object: rclonestore/SMALLFILE (35).txt","domain":"global","reason":"notFound"}]}}
2019/08/23 01:19:11 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 01:19:11 DEBUG : SMALLFILE (35).txt: Couldn't find file - need to transfer
2019/08/23 01:19:11 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 01:19:11 DEBUG : HTTP REQUEST (req 0xc0003b1300)
2019/08/23 01:19:11 DEBUG : GET /storage/v1/b/rclonestore/o?alt=json&maxResults=1&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-103-g85557827-fix-3330-vfs-beta
Authorization: XXXX
Accept-Encoding: gzip

2019/08/23 01:19:11 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 01:19:11 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 01:19:11 DEBUG : HTTP RESPONSE (req 0xc0003b1300)
2019/08/23 01:19:11 DEBUG : HTTP/1.1 200 OK
Content-Length: 839
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Type: application/json; charset=UTF-8
Date: Thu, 22 Aug 2019 23:19:11 GMT
Expires: Thu, 22 Aug 2019 23:19:11 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2UrwoidW84QYb4N9_kj5wEsN6e5SKBaAjgsDkxPHFeLZWDizS_5ML9YvQj2r2sGIGGQaH_LriFkw0QsIPhWcTJ-ecuMjpg

{"kind":"storage#objects","nextPageToken":"ChJSY2xvbmUgV2Vic2l0ZS50eHQ=","items":[{"kind":"storage#object","id":"rclonestore/Rclone Website.txt/1566442439693691","selfLink":"https://www.googleapis.com/storage/v1/b/rclonestore/o/Rclone%20Website.txt","name":"Rclone Website.txt","bucket":"rclonestore","generation":"1566442439693691","metageneration":"1","contentType":"text/plain; charset=utf-8","timeCreated":"2019-08-22T02:53:59.691Z","updated":"2019-08-22T02:53:59.691Z","storageClass":"REGIONAL","timeStorageClassUpdated":"2019-08-22T02:53:59.691Z","size":"0","md5Hash":"1B2M2Y8AsgTpgAmY7PhCfg==","mediaLink":"https://www.googleapis.com/download/storage/v1/b/rclonestore/o/Rclone%20Website.txt?generation=1566442439693691&alt=media","metadata":{"mtime":"2019-08-22T02:53:59.536229700Z"},"crc32c":"AAAAAA==","etag":"CPuqt+m8leQCEAE="}]}
2019/08/23 01:19:11 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 01:19:11 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 01:19:11 DEBUG : HTTP REQUEST (req 0xc0003b1300)
2019/08/23 01:19:11 DEBUG : POST /upload/storage/v1/b/rclonestore/o?alt=json&name=SMALLFILE+%2835%29.txt&predefinedAcl=bucketOwnerFullControl&prettyPrint=false&uploadType=multipart HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-103-g85557827-fix-3330-vfs-beta
Transfer-Encoding: chunked
Authorization: XXXX
Content-Type: multipart/related; boundary=5656ebb51963c907802ba0a6757811ab49d59499224d2afc257034c318c9
Accept-Encoding: gzip

31c
--5656ebb51963c907802ba0a6757811ab49d59499224d2afc257034c318c9
Content-Type: application/json

{"bucket":"rclonestore","contentType":"text/plain; charset=utf-8","metadata":{"mtime":"2019-07-05T19:59:06.718019100+02:00"},"name":"SMALLFILE (35).txt"}

--5656ebb51963c907802ba0a6757811ab49d59499224d2afc257034c318c9

This is a test file
adasdwfwafasfasfas
This is a test file
adasdwfwafasfasfas
This is a test file
adasdwfwafasfasfas
This is a test file
adasdwfwafasfasfas
This is a test file
adasdwfwafasfasfas
This is a test file
adasdwfwafasfasfas
This is a test file
adasdwfwafasfasfas
This is a test file
adasdwfwafasfasfas
This is a test file
adasdwfwafasfasfas
This is a test file
adasdwfwafasfasfas
--5656ebb51963c907802ba0a6757811ab49d59499224d2afc257034c318c9--

0

2019/08/23 01:19:11 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 01:19:12 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 01:19:12 DEBUG : HTTP RESPONSE (req 0xc0003b1300)
2019/08/23 01:19:12 DEBUG : HTTP/1.1 200 OK
Content-Length: 762
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Content-Type: application/json; charset=UTF-8
Date: Thu, 22 Aug 2019 23:19:12 GMT
Etag: CP3c79bOl+QCEAE=
Expires: Mon, 01 Jan 1990 00:00:00 GMT
Pragma: no-cache
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2Uqj4q0IPKOBUEG50xdkzqQL2QPFuQOtyNMrAKyUh_O-S847jqaNRfzATEqiIt6R6lAj6pRQ0E2e2y3keNg9VZX35A7z3Q

{"kind":"storage#object","id":"rclonestore/SMALLFILE (35).txt/1566515952086653","selfLink":"https://www.googleapis.com/storage/v1/b/rclonestore/o/SMALLFILE%20(35).txt","name":"SMALLFILE (35).txt","bucket":"rclonestore","generation":"1566515952086653","metageneration":"1","contentType":"text/plain; charset=utf-8","timeCreated":"2019-08-22T23:19:12.086Z","updated":"2019-08-22T23:19:12.086Z","storageClass":"REGIONAL","timeStorageClassUpdated":"2019-08-22T23:19:12.086Z","size":"408","md5Hash":"rJOdAMRAeOfmEOcwombg9w==","mediaLink":"https://www.googleapis.com/download/storage/v1/b/rclonestore/o/SMALLFILE%20(35).txt?generation=1566515952086653&alt=media","metadata":{"mtime":"2019-07-05T19:59:06.718019100+02:00"},"crc32c":"/QE6Lw==","etag":"CP3c79bOl+QCEAE="}
2019/08/23 01:19:12 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 01:19:12 INFO : SMALLFILE (35).txt: Copied (new)
2019/08/23 01:19:12 INFO :
Transferred: 408 / 408 Bytes, 100%, 924 Bytes/s, ETA 0s
Errors: 0
Checks: 0 / 0, -
Transferred: 1 / 1, 100%
Elapsed time: 400ms

2019/08/23 01:19:12 DEBUG : 7 go routines active
2019/08/23 01:19:12 DEBUG : rclone: Version "v1.48.0-103-g85557827-fix-3330-vfs-beta" finishing with parameters ["rclone" "copy" "F:\TESTFILES\Stigmatest\SMALLFILES\SMALLFILE (35).txt" "Gcloudtest:rclonestore" "-vv" "--dump" "bodies"]

Result: Success! modtime is now correct (same as source file)
Hypothesis: Something wrong in the mount-layer? Maybe this is an rclone problem after all and not a permissions issue. Note that a write cache is being used here in all examples if you think that matters. Tell me if you need me to do a non-cache test.

ncw · August 23, 2019, 7:48am

In your final test the modtime in the upload was sensible "2019-07-05T19:59:06.718019100+02:00"

Not the 1601 value.

I agree it looks like a mount problem, except you said that rclone lsl shows the 1601 time.

We can see quite clearly the 0 time coming from FUSE so Windows must think the file is 0 time too.

So I think some aspect of this file has an empty time...

Can you run Get-Item /path/to/file | Format-List in powershell replacing /path/to/file to the path to the suspect file?

thestigma · August 23, 2019, 1:23pm

Let me clarify that by saying that rclone lsl shows 1601 on a file that looked like it had an empty timestamp in windows after uploading. At that point the file almost certainly had it's modtime bungled, so that in itself isn't an error in rclone. If I rclone lsl on the original local files rclone reports a normal modtime.

I can't remember seeing any empty modtimes on any of the bulk uploads I have done outside the mount, so I doubt it is a error inside the main rclone code. Likely the problem is either in the mount-layer, or in the communication between the two. At least that is my best guess.

The successful last test was specifically not involving the mount.

Do you want me to point this at a file with a missing mod-time after upload, or the intact original file?
Both? .. I will run this and post back in a minute.

thestigma · August 23, 2019, 1:43pm

This is the original local file which has normal modtime.

PS C:\Users> Get-Item "F:\TESTFILES\Stigmatest\SMALLFILES\SMALLFILE (31).txt" | Format-List
Directory: F:\TESTFILES\Stigmatest\SMALLFILES
Name : SMALLFILE (31).txt
Length : 408
CreationTime : 20.08.2019 00:13:54
LastWriteTime : 05.07.2019 19:59:06
LastAccessTime : 20.08.2019 00:13:54
Mode : -a----
LinkType :
Target : {}
VersionInfo : File: F:\TESTFILES\Stigmatest\SMALLFILES\SMALLFILE (31).txt
InternalName:
OriginalFilename:
FileVersion:
FileDescription:
Product:
ProductVersion:
Debug: False
Patched: False
PreRelease: False
PrivateBuild: False
SpecialBuild: False
Language:

This is how it looks after upload to Gcloud (modtime = upload time):

PS C:\Users> Get-Item "P:\SMALLFILE (31).txt" | Format-List
Directory: P:\
Name : SMALLFILE (31).txt
Length : 408
CreationTime : 23.08.2019 01:11:05
LastWriteTime : 23.08.2019 01:11:05
LastAccessTime : 23.08.2019 01:11:05
Mode : ------
LinkType :
Target :
VersionInfo : File: P:\SMALLFILE (31).txt
InternalName:
OriginalFilename:
FileVersion:
FileDescription:
Product:
ProductVersion:
Debug: False
Patched: False
PreRelease: False
PrivateBuild: False
SpecialBuild: False
Language:

Lastly, here is an example from my personal Gdrive (not the same remote as the original issue is about) where I have noticed modtimes being simply missing in windows (or technically 1601 I assume). I add this here because it seems like a strongly related issue. Here - rather than the modtime being set to the upload time it's just blank/1601. I have several of these, and I think all those were transfered via mount - but I don't know if all files transfered this way had the same issue. I don't think so... or I would expect to see even more - but i didn't track this since it's something I noticed later on.

PS C:\Users> Get-Item "X:\Farcry 4 golden ed 1.10 saves.rar" | Format-List
Directory: X:\
Name : Farcry 4 golden ed 1.10 saves.rar
Length : 43659
CreationTime :
LastWriteTime :
LastAccessTime :
Mode : ------
LinkType :
Target :
VersionInfo : File: X:\Farcry 4 golden ed 1.10 saves.rar
InternalName:
OriginalFilename:
FileVersion:
FileDescription:
Product:
ProductVersion:
Debug: False
Patched: False
PreRelease: False
PrivateBuild: False
SpecialBuild: False
Language:

ncw · August 23, 2019, 2:40pm

OK, thanks for that...

I'm a bit confused now about what causes the problem and what doesn't!

Maybe the whole invalid time thing is a red herring - I just tried to set a time 1000 years ago and it worked fine on a gcs bucket. Can you try the same thing on an existing file?

$ rclone touch -vv --dump bodies -t 1001-01-01T00:00:00 TestGoogleCloudStorage:rclone-test1/hello.txt
2019/08/23 15:38:32 DEBUG : rclone: Version "v1.48.0-255-g8118c4a9-filename-encode-beta" starting with parameters ["rclone" "touch" "-vv" "--dump" "bodies" "-t" "1001-01-01T00:00:00" "TestGoogleCloudStorage:rclone-test1/hello.txt"]
2019/08/23 15:38:32 DEBUG : Using config file from "/home/ncw/.rclone.conf"
2019/08/23 15:38:32 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 15:38:32 DEBUG : HTTP REQUEST (req 0xc00048cc00)
2019/08/23 15:38:32 DEBUG : GET /storage/v1/b/rclone-test1/o/hello.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-255-g8118c4a9-filename-encode-beta
Authorization: XXXX
Accept-Encoding: gzip

2019/08/23 15:38:32 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 15:38:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 15:38:32 DEBUG : HTTP RESPONSE (req 0xc00048cc00)
2019/08/23 15:38:32 DEBUG : HTTP/1.1 200 OK
Content-Length: 720
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 14:38:32 GMT
Etag: CNyu1NqJy9kCEAQ=
Expires: Fri, 23 Aug 2019 14:38:32 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2Up1-j4PaIjQwRWBXY4nNnuaSaNtTSLk26BQSfanxjn-9r8G4npazqkEQStD4RhBXBtqXEe8eux_cyUGr47gxu1eY4yzxg

{"kind":"storage#object","id":"rclone-test1/hello.txt/1519905632753500","selfLink":"https://www.googleapis.com/storage/v1/b/rclone-test1/o/hello.txt","name":"hello.txt","bucket":"rclone-test1","generation":"1519905632753500","metageneration":"4","contentType":"text/plain; charset=utf-8","timeCreated":"2018-03-01T12:00:32.589Z","updated":"2019-08-23T14:37:19.454Z","storageClass":"STANDARD","timeStorageClassUpdated":"2018-03-01T12:00:32.589Z","size":"29","md5Hash":"VwRBgj+W1SHTzJKABZGISA==","mediaLink":"https://www.googleapis.com/download/storage/v1/b/rclone-test1/o/hello.txt?generation=1519905632753500&alt=media","metadata":{"mtime":"1001-01-01T00:00:00.000000000Z"},"crc32c":"uuCaYA==","etag":"CNyu1NqJy9kCEAQ="}
2019/08/23 15:38:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 15:38:32 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 15:38:32 DEBUG : HTTP REQUEST (req 0xc000578c00)
2019/08/23 15:38:32 DEBUG : PATCH /storage/v1/b/rclone-test1/o/hello.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-255-g8118c4a9-filename-encode-beta
Content-Length: 99
Authorization: XXXX
Content-Type: application/json
Accept-Encoding: gzip

{"bucket":"rclone-test1","metadata":{"mtime":"1001-01-01T00:00:00.000000000Z"},"name":"hello.txt"}
2019/08/23 15:38:32 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 15:38:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 15:38:32 DEBUG : HTTP RESPONSE (req 0xc000578c00)
2019/08/23 15:38:32 DEBUG : HTTP/1.1 200 OK
Content-Length: 720
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 14:38:32 GMT
Etag: CNyu1NqJy9kCEAU=
Expires: Mon, 01 Jan 1990 00:00:00 GMT
Pragma: no-cache
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2UqP3m8vIC0VDU0nFE6OWDuKNgRBSADU6sd75AgQWhHWQvTv63BzMW-JHw8zgIGvLJRxGM1lamnB0YU58iAFYJcr_oOcNw

{"kind":"storage#object","id":"rclone-test1/hello.txt/1519905632753500","selfLink":"https://www.googleapis.com/storage/v1/b/rclone-test1/o/hello.txt","name":"hello.txt","bucket":"rclone-test1","generation":"1519905632753500","metageneration":"5","contentType":"text/plain; charset=utf-8","timeCreated":"2018-03-01T12:00:32.589Z","updated":"2019-08-23T14:38:32.317Z","storageClass":"STANDARD","timeStorageClassUpdated":"2018-03-01T12:00:32.589Z","size":"29","md5Hash":"VwRBgj+W1SHTzJKABZGISA==","mediaLink":"https://www.googleapis.com/download/storage/v1/b/rclone-test1/o/hello.txt?generation=1519905632753500&alt=media","metadata":{"mtime":"1001-01-01T00:00:00.000000000Z"},"crc32c":"uuCaYA==","etag":"CNyu1NqJy9kCEAU="}
2019/08/23 15:38:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 15:38:32 DEBUG : 5 go routines active
2019/08/23 15:38:32 DEBUG : rclone: Version "v1.48.0-255-g8118c4a9-filename-encode-beta" finishing with parameters ["rclone" "touch" "-vv" "--dump" "bodies" "-t" "1001-01-01T00:00:00" "TestGoogleCloudStorage:rclone-test1/hello.txt"]

$ rclone lsl TestGoogleCloudStorage:rclone-test1/hello.txt
       29 1000-12-31 23:58:45.000000000 hello.txt

thestigma · August 23, 2019, 7:14pm

Here you go. I didn't bother testing this through the mount because it already failed directly via rclone to remote. So hmm... not sure how to make this fit with the other observations. Very strange that you had no problems on the same setup - unless it really is a wrong persmissions setting somewhere.

TLDR of log: same insufficient permissions error when setting modtime. This was done against an existing file (one of those that had gotten it's mod-time not updated).

C:\rclone>rclone touch -vv --dump bodies -t 1001-01-01T00:00:00 "Gcloudtest:rclonestore\SMALLFILE (31).txt"
2019/08/23 21:07:31 DEBUG : rclone: Version "v1.48.0-227-g077b4532-beta" starting with parameters ["rclone" "touch" "-vv" "--dump" "bodies" "-t" "1001-01-01T00:00:00" "Gcloudtest:rclonestore\SMALLFILE (31).txt"]
2019/08/23 21:07:31 DEBUG : Using config file from "C:\rclone\rclone.conf"
2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:31 DEBUG : HTTP REQUEST (req 0xc0000f0b00)
2019/08/23 21:07:31 DEBUG : POST /token HTTP/1.1
Host: oauth2.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Content-Length: 789
Content-Type: application/x-www-form-urlencoded
Accept-Encoding: gzip

assertion=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjRjMTNmMzUyZmQ5N2YxN2ZmMmY3NmYwNTk3NzYzMzcyY2I2MzBhOWIifQ.eyJpc3MiOiJyY2xvbmVzYUByY2xvbmVvbmUtMjQ5ODE4LmlhbS5nc2VydmljZWFjY291bnQuY29tIiwic2NvcGUiOiJodHRwczovL3d3dy5nb29nbGVhcGlzLmNvbS9hdXRoL2RldnN0b3JhZ2UucmVhZF93cml0ZSIsImF1ZCI6Imh0dHBzOi8vb2F1dGgyLmdvb2dsZWFwaXMuY29tL3Rva2VuIiwiZXhwIjoxNTY2NTkwODQxLCJpYXQiOjE1NjY1ODcyNDF9.eKHnYITMOePVxO9F_zVUQzAoOs5LaIUC6aLhrtaX_Mzo5MLH_003FiZbj1LzjhdpEF24ys4Dj3jjzjVGvimAR5Eh--OOMr98sEJYZMfLwiF2fUWagqZpjVLBK0UlfV0AzmyrKIXKETrL3m71-PGcWdzP94qaL2ar1RSngCHT1tt5dszZPbAgsDchg-gtDlzq2eP5u3y6ZX1UbLX-o81UuPpV71RoJdX3Uxr9mkKOopjKNuowm3PECzNHl_RKTPEQymOIYfCKDNi3akuqzzxTabpxrcBkpEcj_249VPaLO9LUuCqZDY4E3hp3Agt-wOCVjJA_aLwxqqj91vNghczvBA&grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer
2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:31 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:31 DEBUG : HTTP RESPONSE (req 0xc0000f0b00)
2019/08/23 21:07:31 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: private
Content-Type: application/json; charset=utf-8
Date: Fri, 23 Aug 2019 19:07:31 GMT
Server: scaffolding on HTTPServer2
Vary: Origin
Vary: X-Origin
Vary: Referer
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Xss-Protection: 0

ca
{
"access_token": "ya29.c.ElptB1SBZbzK_7dGNHePv4qKCtOnBCuG4_wDssVoPNi136BvBTdIDhP_OQtgx0gh7dRwM-0--_D__oNL3rWac_U0dLo5z-AoQSpIOuXd9G3D1Er7ZT7-ZtCWFOo",
"expires_in": 3600,
"token_type": "Bearer"
}
0

2019/08/23 21:07:31 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:31 DEBUG : HTTP REQUEST (req 0xc00018bd00)
2019/08/23 21:07:31 DEBUG : GET /storage/v1/b/rclonestore/o/SMALLFILE%20%2831%29.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Authorization: XXXX
Accept-Encoding: gzip

2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:31 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:31 DEBUG : HTTP RESPONSE (req 0xc00018bd00)
2019/08/23 21:07:31 DEBUG : HTTP/1.1 200 OK
Content-Length: 762
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 19:07:31 GMT
Etag: CPyA7O7Ml+QCEAE=
Expires: Fri, 23 Aug 2019 19:07:31 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2UrxKdtgoLO_0k7rnWYfeLgDOJ7dQzONKQs3DA6b-yFof98Clhm1n6Iimd-nZw0CYDRUvL4Cn4GWJFt9um5iYfXwyVJfugOHlodcnt_0c-PPNfqaXiQ

{"kind":"storage#object","id":"rclonestore/SMALLFILE (31).txt/1566515465486460","selfLink":"https://www.googleapis.com/storage/v1/b/rclonestore/o/SMALLFILE%20(31).txt","name":"SMALLFILE (31).txt","bucket":"rclonestore","generation":"1566515465486460","metageneration":"1","contentType":"text/plain; charset=utf-8","timeCreated":"2019-08-22T23:11:05.486Z","updated":"2019-08-22T23:11:05.486Z","storageClass":"REGIONAL","timeStorageClassUpdated":"2019-08-22T23:11:05.486Z","size":"408","md5Hash":"rJOdAMRAeOfmEOcwombg9w==","mediaLink":"https://www.googleapis.com/download/storage/v1/b/rclonestore/o/SMALLFILE%20(31).txt?generation=1566515465486460&alt=media","metadata":{"mtime":"2019-08-23T01:11:05.316919500+02:00"},"crc32c":"/QE6Lw==","etag":"CPyA7O7Ml+QCEAE="}
2019/08/23 21:07:31 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:31 DEBUG : HTTP REQUEST (req 0xc00018b100)
2019/08/23 21:07:31 DEBUG : PATCH /storage/v1/b/rclonestore/o/SMALLFILE%20%2831%29.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Content-Length: 107
Authorization: XXXX
Content-Type: application/json
Accept-Encoding: gzip

{"bucket":"rclonestore","metadata":{"mtime":"1001-01-01T00:00:00.000000000Z"},"name":"SMALLFILE (31).txt"}
2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:31 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:31 DEBUG : HTTP RESPONSE (req 0xc00018b100)
2019/08/23 21:07:31 DEBUG : HTTP/1.1 403 Forbidden
Content-Length: 160
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 19:07:31 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
Www-Authenticate: Bearer realm="https://accounts.google.com/"
X-Guploader-Uploadid: AEnB2UrLW81byCL1BBgFMVWSGbjlVZFWW1C5PdKjHysTueyLd9ObZ7rAzHmaEDdlWOxbJU7A5KSLxTBnzG4lOtJgwGl4jB1ifA

{"error":{"errors":[{"domain":"global","reason":"insufficientPermissions","message":"Insufficient Permission"}],"code":403,"message":"Insufficient Permission"}}
2019/08/23 21:07:31 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:31 ERROR : Attempt 1/3 failed with 1 errors and: touch: couldn't set mod time: googleapi: Error 403: Insufficient Permission, insufficientPermissions
2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:31 DEBUG : HTTP REQUEST (req 0xc00051f600)
2019/08/23 21:07:31 DEBUG : GET /storage/v1/b/rclonestore/o/SMALLFILE%20%2831%29.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Authorization: XXXX
Accept-Encoding: gzip

2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:31 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:31 DEBUG : HTTP RESPONSE (req 0xc00051f600)
2019/08/23 21:07:31 DEBUG : HTTP/1.1 200 OK
Content-Length: 762
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 19:07:31 GMT
Etag: CPyA7O7Ml+QCEAE=
Expires: Fri, 23 Aug 2019 19:07:31 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2UpjdGIOBnhJRznuEf1qXOSd1OoU5lc47KwpC7XNvTmRctAjEzir3wlH0-GK_0J2W52n7XDiRWnxCXfiEcMwLB0knPPvaiCmRjmeRkO-F_rBSsifeeA

{"kind":"storage#object","id":"rclonestore/SMALLFILE (31).txt/1566515465486460","selfLink":"https://www.googleapis.com/storage/v1/b/rclonestore/o/SMALLFILE%20(31).txt","name":"SMALLFILE (31).txt","bucket":"rclonestore","generation":"1566515465486460","metageneration":"1","contentType":"text/plain; charset=utf-8","timeCreated":"2019-08-22T23:11:05.486Z","updated":"2019-08-22T23:11:05.486Z","storageClass":"REGIONAL","timeStorageClassUpdated":"2019-08-22T23:11:05.486Z","size":"408","md5Hash":"rJOdAMRAeOfmEOcwombg9w==","mediaLink":"https://www.googleapis.com/download/storage/v1/b/rclonestore/o/SMALLFILE%20(31).txt?generation=1566515465486460&alt=media","metadata":{"mtime":"2019-08-23T01:11:05.316919500+02:00"},"crc32c":"/QE6Lw==","etag":"CPyA7O7Ml+QCEAE="}
2019/08/23 21:07:31 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:31 DEBUG : HTTP REQUEST (req 0xc0000f0b00)
2019/08/23 21:07:31 DEBUG : PATCH /storage/v1/b/rclonestore/o/SMALLFILE%20%2831%29.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Content-Length: 107
Authorization: XXXX
Content-Type: application/json
Accept-Encoding: gzip

{"bucket":"rclonestore","metadata":{"mtime":"1001-01-01T00:00:00.000000000Z"},"name":"SMALLFILE (31).txt"}
2019/08/23 21:07:31 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:32 DEBUG : HTTP RESPONSE (req 0xc0000f0b00)
2019/08/23 21:07:32 DEBUG : HTTP/1.1 403 Forbidden
Content-Length: 160
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 19:07:31 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
Www-Authenticate: Bearer realm="https://accounts.google.com/"
X-Guploader-Uploadid: AEnB2Uq9JIoKDH4KgvGyEMqyINzdxP92PEDV5omE5IVaL0KQTunvqa0Sre4G-bgeukPS1Z1GjTx8xn-7QrvDEA2PV-hpsNt3VfjcO4d_LLGTRjk-XDugO10

{"error":{"errors":[{"domain":"global","reason":"insufficientPermissions","message":"Insufficient Permission"}],"code":403,"message":"Insufficient Permission"}}
2019/08/23 21:07:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:32 ERROR : Attempt 2/3 failed with 1 errors and: touch: couldn't set mod time: googleapi: Error 403: Insufficient Permission, insufficientPermissions
2019/08/23 21:07:32 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:32 DEBUG : HTTP REQUEST (req 0xc00051fe00)
2019/08/23 21:07:32 DEBUG : GET /storage/v1/b/rclonestore/o/SMALLFILE%20%2831%29.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Authorization: XXXX
Accept-Encoding: gzip

2019/08/23 21:07:32 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:32 DEBUG : HTTP RESPONSE (req 0xc00051fe00)
2019/08/23 21:07:32 DEBUG : HTTP/1.1 200 OK
Content-Length: 762
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 19:07:32 GMT
Etag: CPyA7O7Ml+QCEAE=
Expires: Fri, 23 Aug 2019 19:07:32 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2UpRDTyj317iXjtQjAYVVKkGXeEvniLwCkMtL1GAU198SQGnmdcpXSBX_dUE6epIYgcj5XHL7Rn7DRZ1mhmuyL2bBQ2UCfvA-FsoZYEN9FG4pj3-xwU

{"kind":"storage#object","id":"rclonestore/SMALLFILE (31).txt/1566515465486460","selfLink":"https://www.googleapis.com/storage/v1/b/rclonestore/o/SMALLFILE%20(31).txt","name":"SMALLFILE (31).txt","bucket":"rclonestore","generation":"1566515465486460","metageneration":"1","contentType":"text/plain; charset=utf-8","timeCreated":"2019-08-22T23:11:05.486Z","updated":"2019-08-22T23:11:05.486Z","storageClass":"REGIONAL","timeStorageClassUpdated":"2019-08-22T23:11:05.486Z","size":"408","md5Hash":"rJOdAMRAeOfmEOcwombg9w==","mediaLink":"https://www.googleapis.com/download/storage/v1/b/rclonestore/o/SMALLFILE%20(31).txt?generation=1566515465486460&alt=media","metadata":{"mtime":"2019-08-23T01:11:05.316919500+02:00"},"crc32c":"/QE6Lw==","etag":"CPyA7O7Ml+QCEAE="}
2019/08/23 21:07:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:32 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:32 DEBUG : HTTP REQUEST (req 0xc000312300)
2019/08/23 21:07:32 DEBUG : PATCH /storage/v1/b/rclonestore/o/SMALLFILE%20%2831%29.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Content-Length: 107
Authorization: XXXX
Content-Type: application/json
Accept-Encoding: gzip

{"bucket":"rclonestore","metadata":{"mtime":"1001-01-01T00:00:00.000000000Z"},"name":"SMALLFILE (31).txt"}
2019/08/23 21:07:32 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:07:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:32 DEBUG : HTTP RESPONSE (req 0xc000312300)
2019/08/23 21:07:32 DEBUG : HTTP/1.1 403 Forbidden
Content-Length: 160
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 19:07:32 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
Www-Authenticate: Bearer realm="https://accounts.google.com/"
X-Guploader-Uploadid: AEnB2UoiH08zByORz-OVe1_3qholW7qcf41fS2wLlrKsgRYmltJDmYglnaIiwQ6mq5TBrA2tobY-511ofrJyrULQa5Tm_Vqr20idoPaeJFvzpq28wZXo8xU

{"error":{"errors":[{"domain":"global","reason":"insufficientPermissions","message":"Insufficient Permission"}],"code":403,"message":"Insufficient Permission"}}
2019/08/23 21:07:32 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:07:32 ERROR : Attempt 3/3 failed with 1 errors and: touch: couldn't set mod time: googleapi: Error 403: Insufficient Permission, insufficientPermissions
2019/08/23 21:07:32 Failed to touch: touch: couldn't set mod time: googleapi: Error 403: Insufficient Permission, insufficientPermissions

thestigma · August 23, 2019, 7:20pm

I also tested the same command on a non-existing file.
Result: no permission errors and modtime on the resulting file is correct:

C:\rclone>rclone touch -vv --dump bodies -t 1001-01-01T00:00:00 "Gcloudtest:rclonestore\SMALLFILE (312).txt"
2019/08/23 21:19:12 DEBUG : rclone: Version "v1.48.0-227-g077b4532-beta" starting with parameters ["rclone" "touch" "-vv" "--dump" "bodies" "-t" "1001-01-01T00:00:00" "Gcloudtest:rclonestore\SMALLFILE (312).txt"]
2019/08/23 21:19:12 DEBUG : Using config file from "C:\rclone\rclone.conf"
2019/08/23 21:19:12 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:19:12 DEBUG : HTTP REQUEST (req 0xc000184c00)
2019/08/23 21:19:12 DEBUG : POST /token HTTP/1.1
Host: oauth2.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Content-Length: 789
Content-Type: application/x-www-form-urlencoded
Accept-Encoding: gzip

assertion=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjRjMTNmMzUyZmQ5N2YxN2ZmMmY3NmYwNTk3NzYzMzcyY2I2MzBhOWIifQ.eyJpc3MiOiJyY2xvbmVzYUByY2xvbmVvbmUtMjQ5ODE4LmlhbS5nc2VydmljZWFjY291bnQuY29tIiwic2NvcGUiOiJodHRwczovL3d3dy5nb29nbGVhcGlzLmNvbS9hdXRoL2RldnN0b3JhZ2UucmVhZF93cml0ZSIsImF1ZCI6Imh0dHBzOi8vb2F1dGgyLmdvb2dsZWFwaXMuY29tL3Rva2VuIiwiZXhwIjoxNTY2NTkxNTQyLCJpYXQiOjE1NjY1ODc5NDJ9.PELqRxyIsNjolpZwVgq1a99y4mZzsV5excje9qOTRwHeL12cmoMxyjVRSjGXwnup1TKH_b2ki49HIkHp3yx_4b6XWoljQTxteJ40IIQs-rozA0KbI4bPbXHbSPJTi4y1V6SsBgRh9NtwhI381drlPPCT9DucakNfmbVJwRiw77V1nV6OsEsPlA2909inKEzEBm8mmQuxEfmO6Sl1HGr1xWUKvuSPU-mfspPzjHZMncSNyLclBYHwmSVKQkmetW1cb9W0vWbO22-ZCXxTDdDjfpoz1PtfQ8lC-_NRRsRNhLNjTR-_NLT5VOUgZZnG2BJmIK3Ge-w8YBqtiemSj_4DQA&grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer
2019/08/23 21:19:12 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:19:12 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:19:12 DEBUG : HTTP RESPONSE (req 0xc000184c00)
2019/08/23 21:19:12 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: private
Content-Type: application/json; charset=utf-8
Date: Fri, 23 Aug 2019 19:19:12 GMT
Server: scaffolding on HTTPServer2
Vary: Origin
Vary: X-Origin
Vary: Referer
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Xss-Protection: 0

ca
{
"access_token": "ya29.c.ElptB_xrZyKS40oGkMrUZDuFwWjXDINyyWPrpfpv5qMWD1dAFuGWjVUYtDbu7L0kZ6HSRwfI0886DYTctl5ru7Q3x6zyQ32xBk_KZaPYGRURtN1diihNIUGGaEI",
"expires_in": 3600,
"token_type": "Bearer"
}
0

2019/08/23 21:19:12 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:19:12 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:19:12 DEBUG : HTTP REQUEST (req 0xc00010f200)
2019/08/23 21:19:12 DEBUG : GET /storage/v1/b/rclonestore/o/SMALLFILE%20%28312%29.txt?alt=json&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Authorization: XXXX
Accept-Encoding: gzip

2019/08/23 21:19:12 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:19:12 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:19:12 DEBUG : HTTP RESPONSE (req 0xc00010f200)
2019/08/23 21:19:12 DEBUG : HTTP/1.1 404 Not Found
Content-Length: 193
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 19:19:12 GMT
Expires: Mon, 01 Jan 1990 00:00:00 GMT
Pragma: no-cache
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2UpvN6HKEt5YQOwQIMD3vWCkNh4DFADwDb0JsjIbm-LA5qHCD0zJUJRTzqTyMSdXO047d75214wf9jgogrLARBaTSXIIlQ

{"error":{"code":404,"message":"No such object: rclonestore/SMALLFILE (312).txt","errors":[{"message":"No such object: rclonestore/SMALLFILE (312).txt","domain":"global","reason":"notFound"}]}}
2019/08/23 21:19:12 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:19:12 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:19:12 DEBUG : HTTP REQUEST (req 0xc000184f00)
2019/08/23 21:19:12 DEBUG : GET /storage/v1/b/rclonestore/o?alt=json&maxResults=1&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Authorization: XXXX
Accept-Encoding: gzip

2019/08/23 21:19:12 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:19:13 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:19:13 DEBUG : HTTP RESPONSE (req 0xc000184f00)
2019/08/23 21:19:13 DEBUG : HTTP/1.1 200 OK
Content-Length: 824
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 19:19:12 GMT
Expires: Fri, 23 Aug 2019 19:19:12 GMT
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2UoIz2k4Lu9C51IICU_GHoqHe2vHZFfmIPFygGn6of7MhbI6IeFuTECKk7bZxqXqJJJdOtoVQeo3Hwa3WhZSnGMt1VZ28A

{"kind":"storage#objects","nextPageToken":"Cg9DaHJvbWVTZXR1cC5leGU=","items":[{"kind":"storage#object","id":"rclonestore/ChromeSetup.exe/1566575757223381","selfLink":"https://www.googleapis.com/storage/v1/b/rclonestore/o/ChromeSetup.exe","name":"ChromeSetup.exe","bucket":"rclonestore","generation":"1566575757223381","metageneration":"1","contentType":"application/octet-stream","timeCreated":"2019-08-23T15:55:57.223Z","updated":"2019-08-23T15:55:57.223Z","storageClass":"REGIONAL","timeStorageClassUpdated":"2019-08-23T15:55:57.223Z","size":"1151544","md5Hash":"YmB7+CsBvp94N50Q+6uEzA==","mediaLink":"https://www.googleapis.com/download/storage/v1/b/rclonestore/o/ChromeSetup.exe?generation=1566575757223381&alt=media","metadata":{"mtime":"2019-08-22T01:34:21.316780500Z"},"crc32c":"xC6aCg==","etag":"CNXLl7ytmeQCEAE="}]}
2019/08/23 21:19:13 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:19:13 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:19:13 DEBUG : HTTP REQUEST (req 0xc000518400)
2019/08/23 21:19:13 DEBUG : POST /upload/storage/v1/b/rclonestore/o?alt=json&name=SMALLFILE+%28312%29.txt&predefinedAcl=bucketOwnerFullControl&prettyPrint=false&uploadType=multipart HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.48.0-227-g077b4532-beta
Transfer-Encoding: chunked
Authorization: XXXX
Content-Type: multipart/related; boundary=49e7f28ee1cc13213e7cbc8994da49f6267f4981aae36625b7ec958477b8
Accept-Encoding: gzip

180
--49e7f28ee1cc13213e7cbc8994da49f6267f4981aae36625b7ec958477b8
Content-Type: application/json

{"bucket":"rclonestore","contentType":"text/plain; charset=utf-8","metadata":{"mtime":"1001-01-01T00:00:00.000000000Z"},"name":"SMALLFILE (312).txt"}

--49e7f28ee1cc13213e7cbc8994da49f6267f4981aae36625b7ec958477b8

--49e7f28ee1cc13213e7cbc8994da49f6267f4981aae36625b7ec958477b8--

0

2019/08/23 21:19:13 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2019/08/23 21:19:13 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:19:13 DEBUG : HTTP RESPONSE (req 0xc000518400)
2019/08/23 21:19:13 DEBUG : HTTP/1.1 200 OK
Content-Length: 759
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Content-Type: application/json; charset=UTF-8
Date: Fri, 23 Aug 2019 19:19:13 GMT
Etag: CLe30fPameQCEAE=
Expires: Mon, 01 Jan 1990 00:00:00 GMT
Pragma: no-cache
Server: UploadServer
Vary: Origin
Vary: X-Origin
X-Guploader-Uploadid: AEnB2UrzC-NGljjDu8meFUosDWyqBVkZRjClKRnWws5KYxkzo0rhr4fby2YpxX4W8Dy0244vQL8UTAZdT4e0knDunYfuOyK4yw

{"kind":"storage#object","id":"rclonestore/SMALLFILE (312).txt/1566587953109943","selfLink":"https://www.googleapis.com/storage/v1/b/rclonestore/o/SMALLFILE%20(312).txt","name":"SMALLFILE (312).txt","bucket":"rclonestore","generation":"1566587953109943","metageneration":"1","contentType":"text/plain; charset=utf-8","timeCreated":"2019-08-23T19:19:13.109Z","updated":"2019-08-23T19:19:13.109Z","storageClass":"REGIONAL","timeStorageClassUpdated":"2019-08-23T19:19:13.109Z","size":"0","md5Hash":"1B2M2Y8AsgTpgAmY7PhCfg==","mediaLink":"https://www.googleapis.com/download/storage/v1/b/rclonestore/o/SMALLFILE%20(312).txt?generation=1566587953109943&alt=media","metadata":{"mtime":"1001-01-01T00:00:00.000000000Z"},"crc32c":"AAAAAA==","etag":"CLe30fPameQCEAE="}
2019/08/23 21:19:13 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2019/08/23 21:19:13 DEBUG : 7 go routines active
2019/08/23 21:19:13 DEBUG : rclone: Version "v1.48.0-227-g077b4532-beta" finishing with parameters ["rclone" "touch" "-vv" "--dump" "bodies" "-t" "1001-01-01T00:00:00" "Gcloudtest:rclonestore\SMALLFILE (312).txt"]

C:\rclone>rclone lsl "Gcloudtest:rclonestore\SMALLFILE (312).txt"
0 1001-01-01 01:00:00.000000000 SMALLFILE (312).txt

arnoldvilleneuve · August 27, 2019, 4:45am

Have we come up with a resolution for this permission issue.

ncw · August 27, 2019, 9:14am

I think what we are seeing here is two problems

something about your gcs setup means you can't run PATCH on existing files. Maybe you've set the bucket to immutable files or something like that (just guessing). That is the root of the issue.
rclone mount on Windows is giving these weird 1601 dates

I think 2. is probably irrelevant to the problem. I do not have problem 1 on my GCS account so there must be some configuration at issue.

I believe the permission required is storage.objects.update - see: https://cloud.google.com/storage/docs/access-control/iam-json

(Sorry I wrote this a few days ago and forgot to press Reply!)

thestigma · August 27, 2019, 1:47pm

I'm also inclined to believe this may be two different problems, especially since I see similar things (modtime issue) happening on my personal teamdrives via mount.

I think we will do a deep-dive on the permission settings and double-check now that we know more specifically what to look for - and revising the modtime issue as a separate bughunt later.

system · November 25, 2019, 1:54pm

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.