GDrive sync issues

gummybear · February 19, 2021, 10:02pm

I'm having issues trying to use rclone to make regular backups of my google drive. Specifically, I would like to make local copies of online gsuite documents (e.g. gdoc > .docx), and only download the new docs whenever the gdoc changes.

When I try using sync, unchanged files that were previously downloaded still get re-downloaded. Specifically, this is happening with native google files (gdoc, gsheet, gslide, etc). Uploaded PDFs and images sync fine. It seems like the reason is because rclone thinks modifications times for the gsuite files differ. Here is an example of a gdoc called testdoc that gets downloaded every time I run sync.

2021/02/19 16:47:30 DEBUG : rclone: Version "v1.51.0" starting with parameters ["rclone" "--config" "/Users/dan/Source/gbackup/.rcloneconf" "sync" "--fast-list" "--progress" "-vv" "gdrive:Test" "/Volumes/Data/test" "--backup-dir=/Volumes/Data/archive/2021/2021-02-19T16-47-30"]
2021-02-19 16:47:35 INFO  : Local file system at /Volumes/Data/test: Waiting for checks to finish
2021-02-19 16:47:35 DEBUG : testdoc.docx: Modification times differ by -1.666s: 2021-02-19 21:42:50.826 +0000 UTC, 2021-02-19 16:42:49.16 -0500 EST
2021-02-19 16:47:35 INFO  : testdoc.docx: Moved (server side)
2021-02-19 16:47:35 INFO  : Local file system at /Volumes/Data/test: Waiting for transfers to finish
2021-02-19 16:47:35 DEBUG : Local file system at /Volumes/Data/test: File to upload is small (6122 bytes), uploading instead of streaming
2021-02-19 16:47:35 DEBUG : testdoc.docx: MD5 = 7cc3dd2e8d9652b1ed588fc122c5e282 OK
2021-02-19 16:47:35 INFO  : testdoc.docx: Copied (new)
2021-02-19 16:47:35 DEBUG : testdoc.docx: Updating size of doc after download to 6122
2021-02-19 16:47:35 INFO  : testdoc.docx: Copied (Rcat, new)

I've tried to compensate for this by using --checksum. When I make changes to the gdoc (add a new line of test), the checksums stop matching, but the size is reported as the same, so it doesn't sync

2021/02/19 16:51:13 DEBUG : rclone: Version "v1.51.0" starting with parameters ["rclone" "--config" "/Users/dan/Source/gbackup/.rcloneconf" "sync" "--fast-list" "--checksum" "--progress" "-vv" "gdrive:Test" "/Volumes/Data/test" "--backup-dir=/Volumes/Data/archive/2021/2021-02-19T16-51-13"]
2021/02/19 16:51:13 DEBUG : Using config file from "/Users/dan/Source/gbackup/.rcloneconf"
2021-02-19 16:51:14 INFO  : Local file system at /Volumes/Data/test: Waiting for checks to finish
2021-02-19 16:51:14 NOTICE: Local file system at /Volumes/Data/test: --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2021-02-19 16:51:14 DEBUG : testdoc.docx: Size of src and dst objects identical
2021-02-19 16:51:14 DEBUG : testdoc.docx: Unchanged skipping

I've read that google is flakey about reporting file size changes, which could be why I was not seeing the file size update. But the checksum seemed reliable. I read that you can add --ignore-size to force just looking at checksum. I tried this, but rclone still checked the file size anyway?

2021/02/19 16:55:30 DEBUG : rclone: Version "v1.51.0" starting with parameters ["rclone" "--config" "/Users/dan/Source/gbackup/.rcloneconf" "sync" "--fast-list" "--checksum" "--ignore-size" "--progress" "-vv" "gdrive:Test" "/Volumes/Data/test" "--backup-dir=/Volumes/Data/archive/2021/2021-02-19T16-55-30"]
2021/02/19 16:55:30 DEBUG : Using config file from "/Users/dan/Source/gbackup/.rcloneconf"
2021-02-19 16:55:31 INFO  : Local file system at /Volumes/Data/test: Waiting for checks to finish
2021-02-19 16:55:31 NOTICE: Local file system at /Volumes/Data/test: --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2021-02-19 16:55:31 DEBUG : testdoc.docx: Size of src and dst objects identical
2021-02-19 16:55:31 DEBUG : testdoc.docx: Unchanged skipping

I'm using

rclone version v1.51.0
macOS 10.15.7 (intel) (darwin/amd64)
go version: go1.14

Looking for advice! Thanks!

asdffdsa · February 19, 2021, 10:04pm

hello and welcome to the forum,

we have gdrive experts that should stop by soon.
in the mean time, that version of rclone is old, you can update here
https://rclone.org/downloads/#script-download-and-install

gummybear · February 21, 2021, 4:40pm

I've upgraded to 1.54 (macports). I'm still seeing the same behavior. Is anyone else seeing this same issue? Docs I upload sync find (PDFs, images, etc) - it is just gsuite docs that don't sync correctly.

Animosity022 · February 21, 2021, 5:25pm

You can increase the time as it's tell you the mod times are slight different so you can make that window bigger.

Missing rclone.conf and a log from the upgrade though so hard to tell if is still the same issue.

gummybear · February 22, 2021, 4:27pm

Thank you! The suggestion of increasing the time seems to have done the trick. I added --modify-time=1s, and now the sync behavior appears to work as expected. I'm going to abandon the --checksum --ignore-size approach since I now have a workable solution.

That said, I'm still curious if I'm misunderstanding how things work, or if there is a bug that should be filed, or if there should be some slightly better documentation about the limitations of google drive. I really appreciate rclone and the work people have put into it. I've used it extensively in the past (both with google drive and S3) and never run into this kind of issue, although the contents never included gsuite documents before. I put in a non-trivial amount of time trying to figure out what went wrong, so I'm wondering if there is something we could do to help make the issue easier to debug for other people in the future (could be as simple as making a pull request to update the docs in places).

Here is the additional information you requested. It still looks to me like --checksum is looking at file sizes even when I use --ignore-size.

Example, unmodified gdoc file incorrectly being copied during a sync (based on time).

2021/02/22 10:52:08 DEBUG : rclone: Version "v1.54.0-DEV" starting with parameters ["rclone" "--config" "/Users/dan/Source/gbackup/.rcloneconf" "sync" "--fast-list" "--progress" "-vv" "gdrive:Test" "/Volumes/Data/test" "--backup-dir=/Volumes/Data/archive/2021/2021-02-22T10-52-08"]
2021/02/22 10:52:08 DEBUG : Using config file from "/Users/dan/Source/gbackup/.rcloneconf"
2021/02/22 10:52:08 DEBUG : Creating backend with remote "gdrive:Test"
2021/02/22 10:52:08 DEBUG : Creating backend with remote "/Volumes/Data/test"
2021-02-22 10:52:08 DEBUG : Creating backend with remote "/Volumes/Data/archive/2021/2021-02-22T10-52-08"
2021-02-22 10:52:09 DEBUG : Local file system at /Volumes/Data/test: Waiting for checks to finish
2021-02-22 10:52:09 DEBUG : testdoc.docx: Modification times differ by -5ms: 2021-02-19 21:51:09.835 +0000 UTC, 2021-02-19 16:51:09.83 -0500 EST
2021-02-22 10:52:09 INFO  : testdoc.docx: Moved (server-side)
2021-02-22 10:52:09 DEBUG : Local file system at /Volumes/Data/test: Waiting for transfers to finish
2021-02-22 10:52:09 DEBUG : Local file system at /Volumes/Data/test: File to upload is small (6136 bytes), uploading instead of streaming
2021-02-22 10:52:09 DEBUG : testdoc.docx: MD5 = 6b4469edd4ae15996de6e079bfb45d0a OK
2021-02-22 10:52:09 INFO  : testdoc.docx: Copied (new)
2021-02-22 10:52:09 DEBUG : testdoc.docx: Updating size of doc after download to 6136
2021-02-22 10:52:09 INFO  : testdoc.docx: Copied (Rcat, new)

Unchanged file, correctly not downloading after adding --checksum.

2021/02/22 10:54:19 DEBUG : rclone: Version "v1.54.0-DEV" starting with parameters ["rclone" "--config" "/Users/dan/Source/gbackup/.rcloneconf" "sync" "--fast-list" "--checksum" "--ignore-size" "--progress" "-vv" "gdrive:Test" "/Volumes/Data/test" "--backup-dir=/Volumes/Data/archive/2021/2021-02-22T10-54-19"]
2021/02/22 10:54:19 DEBUG : Using config file from "/Users/dan/Source/gbackup/.rcloneconf"
2021/02/22 10:54:19 DEBUG : Creating backend with remote "gdrive:Test"
2021/02/22 10:54:20 DEBUG : Creating backend with remote "/Volumes/Data/test"
2021-02-22 10:54:20 DEBUG : Creating backend with remote "/Volumes/Data/archive/2021/2021-02-22T10-54-19"
2021-02-22 10:54:20 DEBUG : Local file system at /Volumes/Data/test: Waiting for checks to finish
2021-02-22 10:54:20 DEBUG : testdoc.docx: Size of src and dst objects identical
2021-02-22 10:54:20 DEBUG : testdoc.docx: Unchanged skipping

Modified file, incorrectly not syncing using --checksum

2021/02/22 10:58:38 DEBUG : rclone: Version "v1.54.0-DEV" starting with parameters ["rclone" "--config" "/Users/dan/Source/gbackup/.rcloneconf" "sync" "--fast-list" "--checksum" "--progress" "-vv" "gdrive:Test" "/Volumes/Data/test" "--backup-dir=/Volumes/Data/archive/2021/2021-02-22T10-58-38"]
2021/02/22 10:58:38 DEBUG : Using config file from "/Users/dan/Source/gbackup/.rcloneconf"
2021/02/22 10:58:38 DEBUG : Creating backend with remote "gdrive:Test"
2021/02/22 10:58:38 DEBUG : Creating backend with remote "/Volumes/Data/test"
2021-02-22 10:58:38 DEBUG : Creating backend with remote "/Volumes/Data/archive/2021/2021-02-22T10-58-38"
2021-02-22 10:58:38 DEBUG : Local file system at /Volumes/Data/test: Waiting for checks to finish
2021-02-22 10:58:38 DEBUG : testdoc.docx: Size of src and dst objects identical
2021-02-22 10:58:38 DEBUG : testdoc.docx: Unchanged skipping

Still not syncing, even after adding --ignore-size to --checksum

2021/02/22 11:00:38 DEBUG : rclone: Version "v1.54.0-DEV" starting with parameters ["rclone" "--config" "/Users/dan/Source/gbackup/.rcloneconf" "sync" "--fast-list" "--checksum" "--ignore-size" "--progress" "-vv" "gdrive:Test" "/Volumes/Data/test" "--backup-dir=/Volumes/Data/archive/2021/2021-02-22T11-00-38"]
2021/02/22 11:00:38 DEBUG : Using config file from "/Users/dan/Source/gbackup/.rcloneconf"
2021/02/22 11:00:38 DEBUG : Creating backend with remote "gdrive:Test"
2021/02/22 11:00:39 DEBUG : Creating backend with remote "/Volumes/Data/test"
2021-02-22 11:00:39 DEBUG : Creating backend with remote "/Volumes/Data/archive/2021/2021-02-22T11-00-38"
2021-02-22 11:00:39 DEBUG : Local file system at /Volumes/Data/test: Waiting for checks to finish
2021-02-22 11:00:39 DEBUG : testdoc.docx: Size of src and dst objects identical
2021-02-22 11:00:39 DEBUG : testdoc.docx: Unchanged skipping

Here is the config, nothing special

[gdrive]
type = drive
scope = drive
root_folder_id = <secrets>
token = {"access_token":"<moresecrets>","token_type":"Bearer","refresh_token":"<evenmoresecrets>","expiry":"2021-02-22T11:49:52.835058-05:00"}

One thing I read that I'm curious about (from the --modify-window documentation)

The default is 1ns unless this is overridden by a remote. For example OS X only stores modification times to the nearest second so if you are reading and writing to an OS X filing system this will be 1s by default.

In what case does 1s become the default? I'm using OSX, but the default was definitely not 1s...

system · April 24, 2021, 12:27pm

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