I have about 5000 large files in a GCS storage bucket. When I mount the bucket and attempt to open the mount in a file window, many of the files are read without issue, but after a while the whole process freezes to a halt and I get 'timeout awaiting response headers' errors as shown below.
Am I missing something obvious?
rclone version)
rclone v1.56.0
debian 10.10 (64 bit)
Google Cloud Storage
rclone copy /tmp remote:tmp)
./rclone mount gcscrypt: /home/Desktop/rclone/gcscrypt --read-only --async-read=True --attr-timeout 720h --dir-cache-time 720h --poll-interval 720h --vfs-read-chunk-size 1M -vv
[gcs]
type = google cloud storage
client_id =
client_secret =
project_number =
object_acl =
bucket_acl =
location =
storage_class =
service_account_file =
[gcscrypt]
type = crypt
remote = gcs
filename_encryption = standard
directory_name_encryption = true
password =
password2 =
-vv flag
2021/08/09 18:23:37 DEBUG : file: ChunkedReader.openRange at 0 length 1048576
2021/08/09 18:23:37 DEBUG : pacer: Reducing sleep to 3.857076ms
2021/08/09 18:23:37 DEBUG : file: ChunkedReader.Read at 8384512 length 1048576 chunkOffset 7340032 chunkSize 8388608
2021/08/09 18:28:37 DEBUG : pacer: low level retry 1/10 (error Get "https://storage.googleapis.com/download/storage/v1/: http2: timeout awaiting response headers)
2021/08/09 18:28:37 DEBUG : pacer: Rate limited, increasing sleep to 1.162815014s
2021/08/09 18:29:34 DEBUG : : forgetting directory cache
2021/08/09 18:29:37 DEBUG : &{file (r)}: >Release: err=<nil>
2021/08/09 18:29:37 DEBUG : &{file (r)}: >Release: err=<nil>
2021/08/09 18:33:37 DEBUG : pacer: low level retry 2/10 (error Get "file: http2: timeout awaiting response headers)
2021/08/09 18:33:37 DEBUG : pacer: Rate limited, increasing sleep to 2.843130073s
2021/08/09 18:38:37 DEBUG : pacer: low level retry 3/10 (error Get "file": http2: timeout awaiting response headers)
2021/08/09 18:38:37 DEBUG : pacer: Rate limited, increasing sleep to 4.163980061s
Any chance you can post the whole log? The snippet does not tell much.
That's all there is. The rest is just the ChunkedReader.openRange etc. This is the part of the log where the error arises.
Can you please post the entire log and not the snippet?
That seems to just be a snippet as the start is missing.
I keep hitting character / file size limits everywhere so I have had to upload to Google.
Latest attempt starts at 18:55:03 - line 75463.
Do you have some mixed regular files with the encrypted files?
2021/08/09 17:46:55 DEBUG : transferList - Sheet1 (3).tsv: Skipping undecryptable file name: illegal base32 data at input byte 12
That's usually that error.
These guys are what concerns me:
2021/08/09 19:14:33 DEBUG : pacer: low level retry 1/10 (error Get "https://storage.googleapis.com/download/storage/v1/b//o/a4rbmbp23onpn2irro2qe5889g7bgvcl1qhrab14uft8cddocf8jmmi52k9ki9nb0btur8m5e7tnh1koprcrpvhrvucu6tc30b880i96m49j9mi86enbbqjf3pc7uu7u35a8l1r54egoesae83tviu829k?generation=1623656813439305&alt=media": stream error: stream ID 9237; INTERNAL_ERROR)
2021/08/09 19:14:33 DEBUG : pacer: Rate limited, increasing sleep to 1.946974693s
2021/08/09 19:14:34 DEBUG : pacer: low level retry 1/10 (error Get "https://storage.googleapis.com/download/storage/v1/b//o/kgljsppa230t66t33cqtqqjb5t7cc6sr70ftg1vhnfedqa1vtp6bes7j1u5q2m2e5mjkq765dol3i6urorf0r0h3ris2n35gmhcoa4jt4fspetjgam0ejdrkats0jcrps22f471n13fvpt7crctdcn04hg?generation=1623411564276239&alt=media": stream error: stream ID 9241; INTERNAL_ERROR)
There was this issue for Google Drive, but I'm not sure what might have changed with GCS that might be related.
opened 10:18AM - 16 Oct 19 UTC
bug
Remote: Drive
IMPORTANT
waiting for upstream...
In the forum [issues were reported with v1.49.4](https://forum.rclone.org/t/1-49… -4-plex-internal-errors-on-google-drive/12108/90).
The issues looked like this
```
2019/09/30 13:36:34 INFO : Google drive root 'crypt': Failed to get StartPageToken: Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&prettyPrint=false&supportsAllDrives=true: stream error: stream ID 1923; INTERNAL_ERROR
2019/09/30 13:42:04 INFO : Google drive root 'crypt': Failed to get StartPageToken: Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&prettyPrint=false&supportsAllDrives=true: stream error: stream ID 1929; INTERNAL_ERROR
2019/10/02 19:36:29 ERROR : IO error: open file failed: Get https://www.googleapis.com/drive/v3/files/XXX?alt=media: stream error: stream ID 1217; INTERNAL_ERROR
```
This is an [internal error from the go standard library HTTP/2 code](https://github.com/golang/go/blob/03bb3e9ad13ef49afbed7e422d21ef6eb00389c1/src/net/http/h2_bundle.go#L1116).
v1.49.4 was accidentally compiled with go1.13 which enabled http/2 by default for google drive for reasons not clear from [the changelog](https://golang.org/doc/go1.13).
Rolling the compiler back to go1.12 with no other code changes fixes the problem which is what was released as v1.49.5
An attempt at a workaround making these errors retriable was put in f9f9d5029b2f37f109454f2ab6533157669f466f but this did not seem effective.
## Problem statement
- go1.12 runs reliably with google drive over HTTP/1
- go1.13 runs unreliably with google drive over HTTP/2
Perhaps @ncw can share his thoughts as well as that's my first look over and what I see as the line you have is related to http2 as well.
asdffdsa
August 9, 2021, 8:51pm
9
hi,
this line shows up twice, is the OP running two rclone mount at that same time?2021/08/09 17:44:54 DEBUG : rclone: Version "v1.56.0" starting with parameters ["./rclone" "mount" "gcscrypt:" "/home//Desktop/rclone/gcscrypt" "--read-only" "--async-read=True" "--attr-timeout" "720h" "--dir-cache-time" "720h" "--poll-interval" "720h" "-vv" "--log-file=/home//Desktop/rclone/rclone2.log"] 2021/08/09 17:46:52 DEBUG : rclone: Version "v1.56.0" starting with parameters ["./rclone" "mount" "gcscrypt:" "/home//Desktop/rclone/gcscrypt" "--read-only" "--async-read=True" "--attr-timeout" "720h" "--dir-cache-time" "720h" "--poll-interval" "720h" "-vv" "--log-file=/home//Desktop/rclone/rclone2.log"]
asdffdsa
August 9, 2021, 8:55pm
11
hi,
There are stops and starts in there:
egrep 'starting|finishing' rclone.log
2021/08/09 17:44:54 DEBUG : rclone: Version "v1.56.0" starting with parameters ["./rclone" "mount" "gcscrypt:" "/home//Desktop/rclone/gcscrypt" "--read-only" "--async-read=True" "--attr-timeout" "720h" "--dir-cache-time" "720h" "--poll-interval" "720h" "-vv" "--log-file=/home//Desktop/rclone/rclone2.log"]
2021/08/09 17:46:52 DEBUG : rclone: Version "v1.56.0" starting with parameters ["./rclone" "mount" "gcscrypt:" "/home//Desktop/rclone/gcscrypt" "--read-only" "--async-read=True" "--attr-timeout" "720h" "--dir-cache-time" "720h" "--poll-interval" "720h" "-vv" "--log-file=/home//Desktop/rclone/rclone2.log"]
2021/08/09 17:53:27 DEBUG : rclone: Version "v1.56.0" finishing with parameters ["./rclone" "mount" "gcscrypt:" "/home//Desktop/rclone/gcscrypt" "--read-only" "--async-read=True" "--attr-timeout" "720h" "--dir-cache-time" "720h" "--poll-interval" "720h" "-vv" "--log-file=/home//Desktop/rclone/rclone2.log"]
2021/08/09 18:13:39 DEBUG : rclone: Version "v1.56.0" starting with parameters ["./rclone" "mount" "gcscrypt:" "/home//Desktop/rclone/gcscrypt" "--read-only" "--async-read=True" "--attr-timeout" "720h" "--dir-cache-time" "720h" "--poll-interval" "720h" "--vfs-read-chunk-size" "1M" "-vv" "--log-file=/home//Desktop/rclone/rclone2.log"]
2021/08/09 18:54:06 DEBUG : rclone: Version "v1.56.0" finishing with parameters ["./rclone" "mount" "gcscrypt:" "/home//Desktop/rclone/gcscrypt" "--read-only" "--async-read=True" "--attr-timeout" "720h" "--dir-cache-time" "720h" "--poll-interval" "720h" "--vfs-read-chunk-size" "1M" "-vv" "--log-file=/home//Desktop/rclone/rclone2.log"]
2021/08/09 18:55:03 DEBUG : rclone: Version "v1.56.0" starting with parameters ["./rclone" "mount" "gcscrypt:" "/home//Desktop/rclone/gcscrypt" "--read-only" "--async-read=True" "--attr-timeout" "720h" "--dir-cache-time" "720h" "--poll-interval" "720h" "--vfs-read-chunk-size" "1M" "--contimeout" "24h" "--timeout" "24h" "-vv" "--log-file=/home//Desktop/rclone/rclone2.log"]
asdffdsa
August 9, 2021, 9:04pm
13
correct, tho the two i mentioned, at the top of the log are both starting, without a finishing in between them.
and the other starting have a finishing before to it.
just trying to understand what that signifies, if anything...
It just means it was killed or terminated in some non graceful way as it was not written the log file.
Yes the first error is the mixed encrypted/unencrypted files - that's not a problem at all.
As you can see from the logs, everything works as expected for 15 minutes or so and then these errors are thrown. This happens everytime and has been happening for sometime (several months now). I have tried everything including speaking with Google, and have posted to this forum as a last resort really as I know how supportive everyone is.
Thanks @Animosity022 for taking a look. I'd be interested to hear what @ncw makes of it.
It is as you shouldn't mix the two. You should remediate that and separate out your crypt / non crypt stuff.
It’s just 1 file I used for testing. GCS has a minimum storage charge so I’ve just left it there for now in case I ever need to test the remote without the crypt again.
Any progress on this at all? Did you manage to take a look @ncw ?
system
October 13, 2021, 12:02pm
20
This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.
