gsutil timeout in every call refreshing access_token

Total
15
Shares

This might be a duplicate but none of the previous answers match my conditions.

I installed gsutil as part of the google-cloud-sdk following https://cloud.google.com/sdk/docs/install. I could configure gcloud properly without errors.

Every time I try to use gsutil, like for example with gsutil -D ls, I get

INFO 0518 14:52:16.412453 base_api.py] Body: (none)
INFO 0518 14:52:16.412517 transport.py] Attempting refresh to obtain initial access_token
DEBUG 0518 14:52:16.412719 multiprocess_file_storage.py] Read credential file
DEBUG 0518 14:52:16.412842 multiprocess_file_storage.py] Read credential file
INFO 0518 14:52:16.412883 reauth_creds.py] Refreshing access_token
INFO 0518 14:53:16.546304 retry_util.py] Retrying request, attempt #1...
DEBUG 0518 14:53:16.546867 http_wrapper.py] Caught socket error, retrying: timed out
DEBUG 0518 14:53:16.547127 http_wrapper.py] Retrying request to url https://storage.googleapis.com/storage/v1/b?alt=blablabla after exception timed out

and more and more of those retries.

I see some users here that experienced the same, for instance this points out to a WAN Blocking setting enabled, that is not my case. Here the OP says that it was a human error regarding proxy settings, but I don’t have any

➜ set | grep -i proxy

The same proxy thing seems to have solved it for another OP

In the same question another user says that it might be due to a conflicting ~/.boto config file, so I deleted it and tried, with the same results.

I tried reinstalling google SDK several times with the same result.

I tried configuring gsutil as a standalone application setting gcloud config set pass_credentials_to_gsutil false and running gsutil config. Again, without luck

This user seems to be experiencing my same problem, but he ends up saying that his solution was to restart the shell (exec -l $SHELL) and quitting/reopening the command line and keep trying until it works…

So my question is, does anyone know a reliable non-proxy related way to solve this retrying issue in gsutil?

EDIT 1:
The output of curl -v https://storage.googleapis.com/storage/v1/b is

*   Trying 2800:3f0:4002:800::2010:443...
* TCP_NODELAY set
*   Trying 172.217.30.240:443...
* TCP_NODELAY set
* Connected to storage.googleapis.com (172.217.30.240) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=US; ST=California; L=Mountain View; O=Google LLC; CN=*.storage.googleapis.com
*  start date: Apr 13 10:15:35 2021 GMT
*  expire date: Jul  6 10:15:34 2021 GMT
*  subjectAltName: host "storage.googleapis.com" matched cert's "*.googleapis.com"
*  issuer: C=US; O=Google Trust Services; CN=GTS CA 1O1
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x564e279b8e10)
> GET /storage/v1/b HTTP/2
> Host: storage.googleapis.com
> user-agent: curl/7.68.0
> accept: */*
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
< HTTP/2 400 
< x-guploader-uploadid: ABg5-Ux5VPhppIWB7G_da1ydkOJWv1BqXepMdpyJDPZ3zbTSRwPoqE44IqaPQMzLvWbSOab0bePewJXiwBXPpus9JDs
< content-type: application/json; charset=UTF-8
< date: Tue, 18 May 2021 19:41:52 GMT
< vary: Origin
< vary: X-Origin
< cache-control: no-cache, no-store, max-age=0, must-revalidate
< expires: Mon, 01 Jan 1990 00:00:00 GMT
< pragma: no-cache
< content-length: 297
< server: UploadServer
< alt-svc: h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
< 
{
  "error": {
    "code": 400,
    "message": "Required parameter: project",
    "errors": [
      {
        "message": "Required parameter: project",
        "domain": "global",
        "reason": "required",
        "locationType": "parameter",
        "location": "project"
      }
    ]
  }
}
* Connection #0 to host storage.googleapis.com left intact

EDIT 2:

The complete output of gsutil -D ls is:

➜ gsutil -D ls
***************************** WARNING *****************************
*** You are running gsutil with debug output enabled.
*** Be aware that debug output includes authentication credentials.
*** Make sure to remove the value of the Authorization header for
*** each HTTP request printed to the console prior to posting to
*** a public medium such as a forum post or Stack Overflow.
***************************** WARNING *****************************
gsutil version: 4.62
checksum: fe14a00285d4702ed626050d0f9ae955 (OK)
boto version: 2.49.0
python version: 3.8.5 (default, Jan 27 2021, 15:41:15) [GCC 9.3.0]
OS: Linux 5.8.0-50-generic
multiprocessing available: True
using cloud sdk: True
pass cloud sdk credentials to gsutil: True
config path(s): /home/username/.config/gcloud/legacy_credentials/[email protected]/.boto
gsutil path: /home/username/google-cloud-sdk/bin/gsutil
compiled crcmod: False
installed via package manager: False
editable install: False
Command being run: /home/username/google-cloud-sdk/platform/gsutil/gsutil -o GSUtil:default_project_id=default_project -o Credentials:use_client_certificate=False -D ls
config_file_list: ['/home/username/.config/gcloud/legacy_credentials/[email protected]/.boto']
config: [('working_dir', '/mnt/pyami'), ('debug', '0'), ('https_validate_certificates', 'true'), ('working_dir', '/mnt/pyami'), ('debug', '0'), ('default_project_id', 'default_project')]
DEBUG 0518 17:46:39.910250 multiprocess_file_storage.py] Read credential file
DEBUG 0518 17:46:39.910444 multiprocess_file_storage.py] Read credential file
INFO 0518 17:46:39.910933 base_api.py] Calling method storage.buckets.list with StorageBucketsListRequest: <StorageBucketsListRequest
 maxResults: 1000
 project: 'default_project'
 projection: ProjectionValueValuesEnum(noAcl, 1)>
INFO 0518 17:46:39.911321 base_api.py] Making http GET to https://storage.googleapis.com/storage/v1/b?alt=json&fields=nextPageToken%2Citems%2Fid&maxResults=1000&project=default_project&projection=noAcl
INFO 0518 17:46:39.911495 base_api.py] Headers: {'accept': 'application/json',
 'accept-encoding': 'gzip, deflate',
 'content-length': '0',
 'user-agent': 'apitools Python/3.8.5 gsutil/4.62 (linux) analytics/disabled '
               'interactive/True command/ls google-cloud-sdk/341.0.0'}
INFO 0518 17:46:39.911611 base_api.py] Body: (none)
INFO 0518 17:46:39.911687 transport.py] Attempting refresh to obtain initial access_token
DEBUG 0518 17:46:39.911900 multiprocess_file_storage.py] Read credential file
DEBUG 0518 17:46:39.912035 multiprocess_file_storage.py] Read credential file
INFO 0518 17:46:39.912081 reauth_creds.py] Refreshing access_token
INFO 0518 17:47:40.014159 retry_util.py] Retrying request, attempt #1...
DEBUG 0518 17:47:40.014368 http_wrapper.py] Caught socket error, retrying: timed out
DEBUG 0518 17:47:40.014440 http_wrapper.py] Retrying request to url https://storage.googleapis.com/storage/v1/b?alt=json&fields=nextPageToken%2Citems%2Fid&maxResults=1000&project=default_project&projection=noAcl after exception timed out
INFO 0518 17:47:41.531516 transport.py] Attempting refresh to obtain initial access_token
DEBUG 0518 17:47:41.532971 multiprocess_file_storage.py] Read credential file
DEBUG 0518 17:47:41.533422 multiprocess_file_storage.py] Read credential file
INFO 0518 17:47:41.533568 reauth_creds.py] Refreshing access_token
INFO 0518 17:48:41.590354 retry_util.py] Retrying request, attempt #2...
DEBUG 0518 17:48:41.590671 http_wrapper.py] Caught socket error, retrying: timed out
DEBUG 0518 17:48:41.590815 http_wrapper.py] Retrying request to url https://storage.googleapis.com/storage/v1/b?alt=json&fields=nextPageToken%2Citems%2Fid&maxResults=1000&project=default_project&projection=noAcl after exception timed out
INFO 0518 17:48:46.107598 transport.py] Attempting refresh to obtain initial access_token
DEBUG 0518 17:48:46.108518 multiprocess_file_storage.py] Read credential file
DEBUG 0518 17:48:46.108928 multiprocess_file_storage.py] Read credential file
INFO 0518 17:48:46.109037 reauth_creds.py] Refreshing access_token
^CDEBUG: Exception stack trace:
    NoneType: None
    
DEBUG: Caught CTRL-C (signal 2) - Exception stack trace:
      File "/home/username/google-cloud-sdk/platform/gsutil/gsutil", line 21, in <module>
        gsutil.RunMain()
      File "/home/username/google-cloud-sdk/platform/gsutil/gsutil.py", line 122, in RunMain
        sys.exit(gslib.__main__.main())
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/__main__.py", line 435, in main
        return _RunNamedCommandAndHandleExceptions(
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/__main__.py", line 631, in _RunNamedCommandAndHandleExceptions
        return command_runner.RunNamedCommand(command_name,
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/command_runner.py", line 410, in RunNamedCommand
        return_code = command_inst.RunCommand()
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/commands/ls.py", line 568, in RunCommand
        for blr in self.WildcardIterator(
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/wildcard_iterator.py", line 484, in IterBuckets
        for blr in self._ExpandBucketWildcards(bucket_fields=bucket_fields):
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/wildcard_iterator.py", line 400, in _ExpandBucketWildcards
        for bucket in self.gsutil_api.ListBuckets(
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/gcs_json_api.py", line 703, in ListBuckets
        bucket_list = self.api_client.buckets.List(apitools_request,
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/third_party/storage_apitools/storage_v1_client.py", line 362, in List
        return self._RunMethod(
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/apitools/apitools/base/py/base_api.py", line 734, in _RunMethod
        http_response = http_wrapper.MakeRequest(
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/apitools/apitools/base/py/http_wrapper.py", line 348, in MakeRequest
        return _MakeRequestNoRetry(
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/apitools/apitools/base/py/http_wrapper.py", line 397, in _MakeRequestNoRetry
        info, content = http.request(
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/vendored/oauth2client/oauth2client/transport.py", line 159, in new_request
        credentials._refresh(orig_request_method)
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/vendored/oauth2client/oauth2client/client.py", line 761, in _refresh
        self._do_refresh_request(http)
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/google-reauth-python/google_reauth/reauth_creds.py", line 112, in _do_refresh_request
        self._update(*reauth.refresh_access_token(
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/google-reauth-python/google_reauth/reauth.py", line 267, in refresh_access_token
        response, content = _reauth_client.refresh_grant(
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/google-reauth-python/google_reauth/_reauth_client.py", line 147, in refresh_grant
        response, content = http_request(
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/google-reauth-python/google_reauth/reauth_creds.py", line 105, in http_request
        response, content = transport.request(
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/vendored/oauth2client/oauth2client/transport.py", line 280, in request
        return http_callable(uri, method=method, body=body, headers=headers,
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/httplib2/python3/httplib2/__init__.py", line 1985, in request
        (response, content) = self._request(
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/httplib2/python3/httplib2/__init__.py", line 1650, in _request
        (response, content) = self._conn_request(
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/httplib2/python3/httplib2/__init__.py", line 1557, in _conn_request
        conn.connect()
      File "/home/username/google-cloud-sdk/platform/gsutil/third_party/httplib2/python3/httplib2/__init__.py", line 1324, in connect
        sock.connect((self.host, self.port))
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/sig_handling.py", line 92, in _SignalHandler
        _final_signal_handlers[signal_num](signal_num, cur_stack_frame)
      File "/home/username/google-cloud-sdk/platform/gsutil/gslib/__main__.py", line 519, in _HandleControlC
        stack_trace = ''.join(traceback.format_list(traceback.extract_stack()))

Solution

After giving up on this I decided to reinstall one last time the whole google-cloud-sdk suite, but this time using the snap version. Installing it via snap solved the issue for me. I think this points to some issue with my environment that was bypassed thanks to the snap containerization.

So no clear answer here, but if anyone is experiencing the same problem giving a chance to snap may solve the issue as it did for me

Leave a Reply

Your email address will not be published. Required fields are marked *