Open file failed: googleapi: got HTTP response code 400 with body: Bad Request

Holtzmann · January 9, 2021, 12:59pm

What is the problem you are having with rclone?

About 2 days ago I have received the errors below after Plex or Emby performed a scan on the folders, usually this occurs after the sonar or radarr indicates that the file has hit the folder and Plex and Emby scan the folder.
I have already checked all the account information and everything is OK.
I use PGBlitz for transportation, but edited by me for better use.

Logs: 2021/01/09 07:16:53 ERROR: HoltzFlix / Series / In the Dark (2019) / Season 02 / In the Dark (2019) - S02E04 - Deal Me In.nfo: vfs cache: failed to download: vfs reader: failed to write to cache file: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 07:17:15 ERROR: HoltzFlix / Series / Inside No. 9 (2014) / Season 03 / Inside No. 9 (2014) - S03E06 - Private View.nfo: vfs cache: failed to download: vfs reader: failed to write to cache file: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 07:22:46 ERROR: HoltzFlix / Series / Raven's Home (2017) / 02 Temp / S02E22 - Pajama Party.480p.nfo: vfs cache: failed to download: vfs reader: failed to write to cache file: open file failed: googleapi: got HTTP response code 400 with body: Bad Request

What is your rclone version (output from `rclone version`)

rclone v1.53.1

os/arch: linux/amd64
go version: go1.15

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

Ubuntu Server 18.04

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

Google Drive / Team Drive

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

[Service]
Type=notify
EnvironmentFile=/opt/appdata/plexguide/rclone.env
ExecStart=/usr/bin/rclone mount tdrive: /mnt/tdrive
--config=/opt/appdata/plexguide/rclone.conf
--log-file=/var/plexguide/logs/rclone-tdrive.log
--log-level NOTICE
--uid=1000 --gid=1000 --umask=002
--allow-other
--bwlimit-file 16M
--dir-cache-time 1000h
--user-agent HoltzFlix
--drive-skip-gdocs
--poll-interval=1m
--vfs-cache-mode full
--cache-dir=/mnt/cache
--vfs-read-ahead=256M
--vfs-cache-max-age 720h
--vfs-cache-poll-interval=1m
--vfs-cache-max-size 120G
--vfs-read-chunk-size 128M
--vfs-read-chunk-size-limit off
--buffer-size=8M
--use-mmap
--vfs-case-insensitive
ExecStop=/bin/fusermount -uz /mnt/tdrive > /dev/null
TimeoutSec=60
User=0
Group=0



#### The rclone config contents with secrets removed.  
<!--  You should use 3 backticks to begin and end your paste to make it readable.   -->

Paste config here




#### A log from the command with the `-vv` flag  
<!-- You should use 3 backticks to begin and end your paste to make it readable.  Or use a service such as https://pastebin.com or https://gist.github.com/   -->

Logs: 2021/01/09 07:16:53 ERROR: HoltzFlix / Series / In the Dark (2019) / Season 02 / In the Dark (2019) - S02E04 - Deal Me In.nfo: vfs cache: failed to download: vfs reader: failed to write to cache file: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 07:17:15 ERROR: HoltzFlix / Series / Inside No. 9 (2014) / Season 03 / Inside No. 9 (2014) - S03E06 - Private View.nfo: vfs cache: failed to download: vfs reader: failed to write to cache file: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 07:22:46 ERROR: HoltzFlix / Series / Raven's Home (2017) / 02 Temp / S02E22 - Pajama Party.480p.nfo: vfs cache: failed to download: vfs reader: failed to write to cache file: open file failed: googleapi: got HTTP response code 400 with body: Bad Request

Animosity022 · January 9, 2021, 1:14pm

That looks like google returned a bad response and without any further debug log, it's a bit tough.

Does it happen all the time with that file ? Can you ls that file?

Holtzmann · January 9, 2021, 1:18pm

Thank you for returning.
I've caught errors with different files, but always the same error.
I stopped the system now and changed the logs from NOTICE to DEBUG and I will try to reproduce the error and post the logs.

Animosity022 · January 9, 2021, 1:19pm

So the file that generates the error, you can validate it / download it / use it after retrying? Or is that file always bad?

Holtzmann · January 9, 2021, 1:25pm

You can see that today's errors were in the NFO files that Emby generated, but the other days they were errors in MKV files. When I received the error, the first thing I tried to do was reproduce through Plex and I was successful (I'm not sure if it was because it was already in cache).
In these files that today have problems, on a machine with Windows and using Drive File Stream I made a copy to my local machine and I was successful.

Animosity022 · January 9, 2021, 1:32pm

I'm confused.

How does Windows and Drive File Stream come into as you have the OS listed as Ubuntu?

Is there another machine generating these files?

Holtzmann · January 9, 2021, 1:36pm

I may have misunderstood, I will try to be more clear.
My server where everything is running (Plex, Emby, Sonarr, Radarr, etc.) is mounted on the machine described above (Ubuntu and rclone using PGBlitz).
The errors I found were listed on the used drive.
When I saw the errors in the files, I tried to perform the reproduction by Plex and Emby and I had no problems.

To check if the file was available for download I did the test on a machine using windows and I was also successful, did you understand?

Animosity022 · January 9, 2021, 1:50pm

Not really as I don't get how Windows / File Stream come into play if yo are trying to test a rclone issue.

Can you stick to the same machine that's having the issue as we have version/OS and can keep the variables the same?

On that same machine you've had the issue, can you download the problematic file? Can you view / play it/ see the contents?

Holtzmann · January 9, 2021, 2:06pm

Yes, I just did this test for the machine in question and I had no problems.
I cannot say when the problem will occur, in 2 days I had errors in 7 different files (MKV / MP4 and NFO).

random404 · January 9, 2021, 7:24pm

I started having the same issue a few hours ago. Everything worked fine for months.

Anyone else?

Animosity022 · January 9, 2021, 8:59pm

Not me as I've had zero of these ever.

random404 · January 9, 2021, 9:03pm

I'm having this now for many files... Can't even rclone copy to my disk anymore.

And in the API console, there isn't any error:

but I keep getting http response code 400 bad request

random404 · January 9, 2021, 9:12pm

2021/01/09 18:06:47 DEBUG : rclone: Version "v1.53.3" starting with parameters ["rclone" "copy" "1:REDACTED/REDACTED" "." "-vvvv"]
2021/01/09 18:06:47 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2021/01/09 18:06:47 DEBUG : Creating backend with remote "1:REDACTED/REDACTED"
2021/01/09 18:06:48 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=566559356161, userRateLimitExceeded)
2021/01/09 18:06:48 DEBUG : pacer: Rate limited, increasing sleep to 1.201553298s
2021/01/09 18:06:49 DEBUG : pacer: Reducing sleep to 0s
2021/01/09 18:06:50 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=566559356161, userRateLimitExceeded)
2021/01/09 18:06:50 DEBUG : pacer: Rate limited, increasing sleep to 1.568967025s
2021/01/09 18:06:50 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=566559356161, userRateLimitExceeded)
2021/01/09 18:06:50 DEBUG : pacer: Rate limited, increasing sleep to 2.77078239s
2021/01/09 18:06:52 DEBUG : pacer: Reducing sleep to 0s
2021/01/09 18:06:55 DEBUG : fs cache: adding new entry for parent of "1:REDACTED/REDACTED", "1:REDACTED"
2021/01/09 18:06:55 DEBUG : Creating backend with remote "."
2021/01/09 18:06:55 DEBUG : fs cache: renaming cache item "." to be canonical "/root"
2021/01/09 18:06:56 DEBUG : REDACTED: Sizes differ (src 1318618653 vs dst 723057638)
2021/01/09 18:06:56 DEBUG : REDACTED: Starting multi-thread copy with 4 parts of size 314.438M
2021/01/09 18:06:56 DEBUG : REDACTED: multi-thread copy: stream 4/4 (989134848-1318618653) size 314.220M starting
2021/01/09 18:06:56 DEBUG : REDACTED: multi-thread copy: stream 2/4 (329711616-659423232) size 314.438M starting
2021/01/09 18:06:56 DEBUG : REDACTED: multi-thread copy: stream 1/4 (0-329711616) size 314.438M starting
2021/01/09 18:06:56 DEBUG : REDACTED: multi-thread copy: stream 3/4 (659423232-989134848) size 314.438M starting
2021/01/09 18:06:56 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=566559356161, userRateLimitExceeded)
2021/01/09 18:06:56 DEBUG : pacer: Rate limited, increasing sleep to 1.222127414s
2021/01/09 18:06:56 DEBUG : pacer: Reducing sleep to 0s
2021/01/09 18:06:56 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=566559356161, userRateLimitExceeded)
2021/01/09 18:06:56 DEBUG : pacer: Rate limited, increasing sleep to 1.202950526s
2021/01/09 18:06:56 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=566559356161, userRateLimitExceeded)
2021/01/09 18:06:56 DEBUG : pacer: Rate limited, increasing sleep to 2.257211325s
2021/01/09 18:06:57 DEBUG : pacer: Reducing sleep to 0s
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 3/4 failed: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 18:06:58 DEBUG : REDACTED: Reopening on read failure after 11205607 bytes: retry 1/10: context canceled
2021/01/09 18:06:58 DEBUG : REDACTED: Reopening on read failure after 5618662 bytes: retry 1/10: context canceled
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 1/4 failed: multpart copy: failed to open source: open file failed: Get "https://www.googleapis.com/drive/v3/files/1DQ3INtvM-L2GsYMyNFjwSQqs5ImriH1k?alt=media": context canceled
2021/01/09 18:06:58 DEBUG : REDACTED: Reopen failed after 11205607 bytes read: open file failed: Get "https://www.googleapis.com/drive/v3/files/1DQ3INtvM-L2GsYMyNFjwSQqs5ImriH1k?alt=media": context canceled
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 4/4 failed: multpart copy: read failed: context canceled
2021/01/09 18:06:58 DEBUG : REDACTED: Reopen failed after 5618662 bytes read: open file failed: Get "https://www.googleapis.com/drive/v3/files/1DQ3INtvM-L2GsYMyNFjwSQqs5ImriH1k?alt=media": context canceled
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 2/4 failed: multpart copy: read failed: context canceled
2021/01/09 18:06:58 ERROR : REDACTED: Failed to copy: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 18:06:58 ERROR : Attempt 1/3 failed with 1 errors and: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 18:06:58 DEBUG : REDACTED: Sizes differ (src 1318618653 vs dst 1000340455)
2021/01/09 18:06:58 DEBUG : REDACTED: Starting multi-thread copy with 4 parts of size 314.438M
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 1/4 (0-329711616) size 314.438M starting
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 2/4 (329711616-659423232) size 314.438M starting
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 3/4 (659423232-989134848) size 314.438M starting
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 4/4 (989134848-1318618653) size 314.220M starting
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 4/4 failed: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 1/4 failed: multpart copy: failed to open source: open file failed: Get "https://www.googleapis.com/drive/v3/files/1DQ3INtvM-L2GsYMyNFjwSQqs5ImriH1k?alt=media": context canceled
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 3/4 failed: multpart copy: failed to open source: open file failed: Get "https://www.googleapis.com/drive/v3/files/1DQ3INtvM-L2GsYMyNFjwSQqs5ImriH1k?alt=media": context canceled
2021/01/09 18:06:58 DEBUG : REDACTED: multi-thread copy: stream 2/4 failed: multpart copy: failed to open source: open file failed: Get "https://www.googleapis.com/drive/v3/files/1DQ3INtvM-L2GsYMyNFjwSQqs5ImriH1k?alt=media": context canceled
2021/01/09 18:06:58 ERROR : REDACTED: Failed to copy: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 18:06:58 ERROR : Attempt 2/3 failed with 1 errors and: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 18:06:59 DEBUG : REDACTED: Sizes differ (src 1318618653 vs dst 0)
2021/01/09 18:06:59 DEBUG : REDACTED: Starting multi-thread copy with 4 parts of size 314.438M
2021/01/09 18:06:59 DEBUG : REDACTED: multi-thread copy: stream 4/4 (989134848-1318618653) size 314.220M starting
2021/01/09 18:06:59 DEBUG : REDACTED: multi-thread copy: stream 2/4 (329711616-659423232) size 314.438M starting
2021/01/09 18:06:59 DEBUG : REDACTED: multi-thread copy: stream 1/4 (0-329711616) size 314.438M starting
2021/01/09 18:06:59 DEBUG : REDACTED: multi-thread copy: stream 3/4 (659423232-989134848) size 314.438M starting
2021/01/09 18:06:59 DEBUG : REDACTED: multi-thread copy: stream 1/4 failed: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 18:06:59 DEBUG : REDACTED: Reopening on read failure after 18906 bytes: retry 1/10: context canceled
2021/01/09 18:06:59 DEBUG : REDACTED: multi-thread copy: stream 4/4 failed: multpart copy: failed to open source: open file failed: Get "https://www.googleapis.com/drive/v3/files/1DQ3INtvM-L2GsYMyNFjwSQqs5ImriH1k?alt=media": context canceled
2021/01/09 18:06:59 DEBUG : REDACTED: Reopen failed after 18906 bytes read: open file failed: Get "https://www.googleapis.com/drive/v3/files/1DQ3INtvM-L2GsYMyNFjwSQqs5ImriH1k?alt=media": context canceled
2021/01/09 18:06:59 DEBUG : REDACTED: multi-thread copy: stream 3/4 failed: multpart copy: read failed: context canceled
2021/01/09 18:06:59 DEBUG : REDACTED: multi-thread copy: stream 2/4 failed: multpart copy: failed to open source: open file failed: Get "https://www.googleapis.com/drive/v3/files/1DQ3INtvM-L2GsYMyNFjwSQqs5ImriH1k?alt=media": context canceled
2021/01/09 18:06:59 ERROR : REDACTED: Failed to copy: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 18:06:59 ERROR : Attempt 3/3 failed with 1 errors and: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request
2021/01/09 18:06:59 INFO :
Transferred: 16.063M / 16.063 MBytes, 100%, 5.659 MBytes/s, ETA 0s
Errors: 1 (retrying may help)
Elapsed time: 11.8s

2021/01/09 18:06:59 DEBUG : 7 go routines active
2021/01/09 18:06:59 Failed to copy: multpart copy: failed to open source: open file failed: googleapi: got HTTP response code 400 with body: Bad Request

VBB · January 9, 2021, 10:17pm

Just got my first while streaming via Plex:

ReadFileHandle.Read error: low level retry 1/10: open file failed: googleapi: got HTTP response code 400 with body: Bad Request

I normally get these randomly, due to pausing too long, etc.:

ReadFileHandle.Read error: low level retry 1/10: read tcp i/o timeout

Same version of Rclone for both, same mount, established roughly four days ago.

Dual-O · January 9, 2021, 10:59pm

I've got this error 15 times since yesterday.

vfs cache: failed to download: vfs reader: failed to write to cache file: open file failed: googleapi: got HTTP response code 400 with body: Bad Request

VBB · January 9, 2021, 11:19pm

Well, we're all doing different things here, apparently. One person is copying, the other streaming, and the third downloading (which is the same thing, I get it...)

I can only speak for my own setup, which does not involve cache, team drives, or service accounts, and so far (knock on wood) I've only had one single instance of this error. This is with a few streams going pretty much 24/7.

system · March 11, 2021, 7:19pm

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