Storage: TimeoutGuard raises TimeoutException even though upload successful

[mcsimps2]

Environment Details:

• Using google-cloud-storage==1.23.0 and 1.24.1
• Using Mac OSX 10.14 and Windows 7 64 bit
• Using Python 3.7.3

Issue: A file can upload completely to Google Cloud Storage, yet still raise a TimeoutException if the upload process took longer than ~60 seconds (not 100% sure on the timedelta, but I'm guessing that it's 60 seconds from a brief analysis of the code).

Details The use of AuthorizedSession.request for blob uploads in the Google Cloud Storage Python library causes an unwarranted TimeoutException. The TimeoutGuard class raises an unnecessary TimeoutException on file uploads to Cloud Storage even when the Cloud Storage server is responding in a timely manner to file uploads. In fact, a file can completely upload and the TimeoutGuard will still raise a TimeoutException even though a true request timeout never occurred. The reason why is explained below.

Steps to reproduce:
I first encountered this when uploading a large file (1 GB) on a medium upload connection (10 Mbps upload). Although the upload was technically successful, I was still receiving a TimeoutException at the end of the upload from a call to blob.upload_from_filename(filepath) (a resumable upload, not multipart upload).
The stacktrace is below:

  File "site-packages\google\cloud\storage\blob.py", line 1320, in upload_from_filename
  File "site-packages\google\cloud\storage\blob.py", line 1265, in upload_from_file
  File "site-packages\google\cloud\storage\blob.py", line 1175, in _do_upload
  File "site-packages\google\cloud\storage\blob.py", line 1122, in _do_resumable_upload
  File "site-packages\google\resumable_media\requests\upload.py", line 425, in transmit_next_chunk
  File "site-packages\google\resumable_media\requests\_helpers.py", line 136, in http_request
  File "site-packages\google\resumable_media\_helpers.py", line 150, in wait_and_retry
  File "site-packages\google\auth\transport\requests.py", line 287, in request
  File "site-packages\google\auth\transport\requests.py", line 110, in __exit__
requests.exceptions.Timeout" 

The core of the issue is the TimeoutGuard class when used in a context like AuthorizedSession.request. Specifically, look at the following code in the aforementioned method:

with TimeoutGuard(timeout) as guard:
            response = super(AuthorizedSession, self).request(
                method,
                url,
                data=data,
                headers=request_headers,
                timeout=timeout,
                **kwargs
            )
        timeout = guard.remaining_timeout

There are two timeouts going on. One of them is a true request timeout used by the requests library (note AuthorizedSession is a subclass of requests.Session), and this is functioning correctly. The other timeout is a naive timeout set by TimeoutGuard that is causing problems. Essentially, it starts a clock that will raise a TimeoutException if a certain amount of time passes, even if the Google Cloud Storage servers are responding in a timely manner. In this case, the requests library will not raise a TimeoutException (because a true network timeout never occurred), but the TimeoutGuard will.

This causes issues with large files uploads or slow internet connections. If a user tries to upload a file that takes a long time to upload, then, even if the file upload is successful and didn't raise a TimeoutException from the requests library (i.e. server was responding in a timely fashion the entire upload), during TimeoutGuard.__exit__, the TimeoutGuard will raise an unsolicited TimeoutException.

Here's a walkthrough of the error:
(1) File upload initiated
(2) File uploads for a couple minutes, exceeding the default timeout of 60/61 seconds (resumable_media/requests/_helper.py _DEFAULT_CONNECT_TIMEOUT and _DEFAULT_READ_TIMEOUT, although it looks like the TimeGuard will take the minimum of the two) that the TimeGuard uses. The server is responding normally to all chunk uploads. TimeoutException is never thrown from the Python requests library because the server is consistently responding.
(3) File finishes upload, TimeoutGuard raises TimeoutException even though file upload was successful.

I've been able to work around this problem by monkeypatching the TimeoutGuard code, but I believe a proper fix is needed in the codebase. I would be happy to contribute or open a pull request if a maintainer can elaborate on the need for the TimeoutGuard TimeoutException when there is already a TimeoutException being used by the requests.Session class.

[mcsimps2]

I also realize that it would be wise to split such large files into a multi-part upload, but the issue still remains, especially for slow internet connections.

[IlyaFaer]

@plamut, PTAL

[plamut]

(disclaimer: speaking from the top of my head, would need to check the code to confirm)

Not a definite answer, but the motivation for adding a TimeoutGuard was to support customizable total timeouts for the underlying operations, when these operations can potentially involve multiple requests.

For example, sometimes there is a Future object sitting on top that wants to timeout after X seconds, even though each individual underlying request would take less than X seconds. This was needed to support some use case scenarios in BigQuery.

With that said, it is possible that this addition broke the expected semantics in other use cases, e.g. where timeout is expected to represent a per-request timeout.

If there is no explicit timeout given (timeout=None), then the TimeoutGuard should act as a no-op. I think the following paragraph is the key:

File uploads for a couple minutes, exceeding the default timeout of 60/61 seconds (...) that the TimeGuard uses.

IIRC, this is what happens - the library user provides no explicit timeout, but unlike some other libraries, this library also defines a default timeout (60, 61), which is passed to the TimeoutGuard. However, that timeout is probably meant as a timeout for each requests request, and not the total timeout. As the requests docs explain:

timeout is not a time limit on the entire response download; rather, an exception is raised if the server has not issued a response for timeout seconds (more precisely, if no bytes have been received on the underlying socket for timeout seconds). If no timeout is specified explicitly, requests do not time out.

@mcsimps2 Does this sound plausible? From the issue description it seems to me that your application does not use explicit timeouts, is that correct?

(in which case the reported timeout error is indeed a bug - thanks for reporting it!)

Update: Classified as P1, as this can break large file uploads, yet no obvious and reasonable workaround exists (monkeypatching does not count).

[mcsimps2]

Ah, that does make sense - I see how that's useful if you have multiple requests going on and need to cancel an operation mid-way through the sequence of requests if the "clock" timeout was exceeded.

You're correct, I do not set any explicit timeouts when calling the code, so any non-null timeout populated to the TimeoutGuard must be coming from a library default.

However, that timeout is probably meant as a timeout for each requests request, and not the total timeout.

As a quick check (and for debugging purposes only), I can verify that setting the timeout passed to TimeoutGuard to None, while still passing the read and connect timeouts to requests per the timeout parameter, does indeed stop this issue from happening in the AuthorizedSession.request function and allows me to successfully complete a large/slow upload operation.

So it seems that, perhaps, specifying a separate timeout to pass to TimeoutGuard in addition to the one we want to pass to the requests library would remediate this problem, although that might be a naive fix since I have only looked at a very limited portion of the codebase, and it would be one more method argument to worry about.

I would be happy to run any tests that would be helpful since I have access to big files and a slow network.

[plamut]

@mcsimps2 Thanks for the quick feedback, it seems that the fix could be pretty straightforward. It might even make sense to rename timeout to total_timeout in order to better distinguish it from the timeout passed to the requests transport...

The issue can probably also be reproduced by artificially throttling one's internet connection, but if there is a need to access a big file, I will let you know. Or for verifying a patch when ready as a part of a PR review, that would also be cool!

[plamut]

@mcsimps2 FYI, I opened a pull request in the google-auth library.

The timeout parameter no longer affects the TimeoutGuard, and instead a separate max_allowed_time parameter is added to control it. Its value is None by default, making the TimeoutGuard a no-op by default as well.

If you wish, you can already try it out by using the google-auth version from the PR branch, but otherwise there will probably be a new release soon anyway, and the Storage lib will just need a version bump of the google-auth dependency.

[mcsimps2]

Awesome, thank you for pushing this forward so quickly - much appreciated! This will help a lot, I'm looking forward to the next release

[plamut]

@mcsimps2 The most recent google-auth release google-auth==1.11.0 contains the change that separates transport timeouts from the total time wall clock timeout. The latter is None by default, meaning that TimoutGuard should not be raising unnecessary Timeout errors anymore.

Until a new storage lib release is made, you could try manually pinning google-auth to the abovementioned version, resolving this issue.

Also, thanks for the very good and detailed report, it made diagnosing the issue much faster. 👍