Gdrive reads: 30sec delay before first chunk (not write!)

[pico_prob]

What is the problem you are having with rclone?

Reading from gdrive takes an initial 30±5sec delay before data arrives. This happens download only

I use my own API key and I don't run into 403s. Otherwise I thought this thread

https://forum.rclone.org/t/copy-download-takes-40-50-sec-before-receiving-first-chunk-byte-from-google-drive/8320

was my problem. But trying the suggested options didn't help.

Further infos:

• I just got my api key 1-2 weeks ago and I didn't publish my "gdrive app". The tokens I get seem to be valid for an hour only.
• I have a shared folder with unlimited space. However, both inside and outside the shared folder showed the symptom
• No improvement on repetition
• I plan to use the shared folder for the plex media folder. BTW as this seems to be a common use case: Is there a 'best practice' rclone setup somewhere?

What is your rclone version (output from rclone version)

rclone v1.54.0
- os/arch: linux/amd64
- go version: go1.15.7

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Debian 9

Which cloud storage system are you using? (eg Google Drive)

Google Drive

The command you were trying to run (eg rclone copy /tmp remote:tmp)

same result for mount and copy:

# 1.
rclone mount gdr1:/ ~/mnt/gtest -vv
# 2.
rclone mount gdr1:/ ~/mnt/gtest -vv  --dir-cache-time 48h --vfs-read-chunk-size 128M --buffer-size 128M
# 3.
rclone copy --progress -vv gdr1:/100mb.test ~/tmp/

The rclone config contents with secrets removed.

[gdr1]
type = drive
client_id = num-alphaNum.apps.googleusercontent.com
client_secret = secret
scope = drive
token = {"access_token": "token", "token_type": "Bearer",
         "refresh_token": "token", "expiry": "2021-03-06T22:52:44.941168839+01:00"}
root_folder_id = alphaNumDash

A log from the command with the -vv flag

pastebin

[asdffdsa (jojothehumanmonkey)]

hello and welcome to the forum,

can you post a debug log of the rclone copy, that would be easier to figure out the problem

[pico_prob]

To me the mount protocol seems to make the delay between call and response more evident than here.
Read:

2021/03/07 11:55:49 DEBUG : rclone: Version "v1.54.0" starting with parameters ["rclone" "copy" "--log-file=rclone_read_delay.log" "-vv" "gdr1:/100mb.test" "/home/pico/tmp/"]
2021/03/07 11:55:49 DEBUG : Using config file from "/home/pico/.config/rclone/rclone.conf"
2021/03/07 11:55:49 DEBUG : Creating backend with remote "gdr1:/100mb.test"
2021/03/07 11:55:50 DEBUG : fs cache: adding new entry for parent of "gdr1:/100mb.test", "gdr1:"
2021/03/07 11:55:50 DEBUG : Creating backend with remote "/home/pico/tmp/"
2021/03/07 11:55:50 DEBUG : 100mb.test: Need to transfer - File not found at Destination
2021/03/07 11:56:21 DEBUG : 100mb.test: MD5 = 9b5183f05b62ca114c467945467050be OK
2021/03/07 11:56:21 INFO  : 100mb.test: Copied (new)
2021/03/07 11:56:21 INFO  :
Transferred:          100M / 100 MBytes, 100%, 3.201 MBytes/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:        32.2s

2021/03/07 11:56:21 DEBUG : 4 go routines active

For comparison write command (testfile deteted on destination prior to command):

2021/03/07 12:08:52 DEBUG : rclone: Version "v1.54.0" starting with parameters ["rclone" "copy" "--log-file=rclone_write.log" "-vv" "/home/pico/tmp/100mb.test" "gdr1:/"]
2021/03/07 12:08:52 DEBUG : Creating backend with remote "/home/pico/tmp/100mb.test"
2021/03/07 12:08:52 DEBUG : Using config file from "/home/pico/.config/rclone/rclone.conf"
2021/03/07 12:08:52 DEBUG : fs cache: adding new entry for parent of "/home/pico/tmp/100mb.test", "/home/pico/tmp"
2021/03/07 12:08:52 DEBUG : Creating backend with remote "gdr1:/"
2021/03/07 12:08:52 DEBUG : fs cache: renaming cache item "gdr1:/" to be canonical "gdr1:"
2021/03/07 12:08:52 DEBUG : 100mb.test: Need to transfer - File not found at Destination
2021/03/07 12:08:53 DEBUG : 100mb.test: Sending chunk 0 length 8388608
2021/03/07 12:08:53 DEBUG : 100mb.test: Sending chunk 8388608 length 8388608
2021/03/07 12:08:54 DEBUG : 100mb.test: Sending chunk 16777216 length 8388608
2021/03/07 12:08:55 DEBUG : 100mb.test: Sending chunk 25165824 length 8388608
2021/03/07 12:08:56 DEBUG : 100mb.test: Sending chunk 33554432 length 8388608
2021/03/07 12:08:56 DEBUG : 100mb.test: Sending chunk 41943040 length 8388608
2021/03/07 12:08:57 DEBUG : 100mb.test: Sending chunk 50331648 length 8388608
2021/03/07 12:08:58 DEBUG : 100mb.test: Sending chunk 58720256 length 8388608
2021/03/07 12:08:59 DEBUG : 100mb.test: Sending chunk 67108864 length 8388608
2021/03/07 12:08:59 DEBUG : 100mb.test: Sending chunk 75497472 length 8388608
2021/03/07 12:09:00 DEBUG : 100mb.test: Sending chunk 83886080 length 8388608
2021/03/07 12:09:01 DEBUG : 100mb.test: Sending chunk 92274688 length 8388608
2021/03/07 12:09:02 DEBUG : 100mb.test: Sending chunk 100663296 length 4194304
2021/03/07 12:09:03 DEBUG : 100mb.test: MD5 = 9b5183f05b62ca114c467945467050be OK
2021/03/07 12:09:03 INFO  : 100mb.test: Copied (new)
2021/03/07 12:09:03 INFO  :
Transferred:          100M / 100 MBytes, 100%, 8.993 MBytes/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:        11.5s

2021/03/07 12:09:03 DEBUG : 4 go routines active

[pico_prob]

Hm... I am a bit clueless about this. I'am happy for any suggestions.

• I find surprising that the issue only touches read, not write. In general I'd expect writes to be slower than reads.
• The delay of close to 30s (ref: pastebin: line 18, 19) looks a bit like an arbitrary timespan, like a slashing. However there are no indications of slashing in the logs. Maybe there's some other places/procedures to look for indication?
• Since the connection to remote is opened right away (ref: pastebin: line 18, 19), I assume that it's not caused by some network latency.
• It would be of great value to me, if someone could judge on my API key state. It would make sense for google to limit the access. And I remember even reading something like that. I haven't attempted to publish my app, yet. I am fearing some review process. The token expiry of one hour seems oddly short.

Again: Any suggestions are welcome and taken seriously!
I don't expect spoon-feeding

[ncw (Nick Craig-Wood)]

Try adding -vv --dump headers to see the HTTP requests and responses. That may shed some light on the matter.

[pico_prob]

@ncw

--dump headers

You'll find a 30sec delay between request and response at line 132, 133 . All responses are 200s.

BTW: Thanks for the quick reply!!

[ncw (Nick Craig-Wood)]

That looks very much like that is google drive waiting for 30 seconds before responding.

It could be something in your network path - are you using a proxy?

I'd get wireshark on the job now and see if there really are any packets being sent or received in that 30 seconds gap.

30 seconds is such a round number it sounds like something timing out which would fit for the proxy idea.