felix-hilden / tekore

Spotify Web API client for Python 3
https://tekore.rtfd.org
MIT License
207 stars 20 forks source link

Retry token refresh #254

Closed alexpogue closed 3 years ago

alexpogue commented 3 years ago

Heyo, it's me again appreciating your fine work!

I have seen sometimes that when the automatically-refreshing token tries to refresh, it fails with:

requests.exceptions.ConnectionError: HTTPSConnectionPool(host='accounts.spotify.com', port=443): Max retries exceeded with url: /api/token (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7febcff0cc88>: Failed to establish a new connection: [Errno 101] Network is unreachable'))

I am using Tekore to make 15,000 Spotify API calls at a time, so that could have something to do with the error. I was looking for something like RetryingRefreshingToken, but could not find it.

Code:

def init_spotipy():
    spotify_client_id = app.config['SPOTIFY_CLIENT_ID']
    spotify_client_secret = app.config['SPOTIFY_CLIENT_SECRET']
    app_token = request_client_token(spotify_client_id, spotify_client_secret)

    # use RetryingSender to retry when we are rate limited by spotify API
    sender = RetryingSender(retries=100)
    return Spotify(app_token, sender=sender)

Full stack trace:

Traceback (most recent call last):
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/celery/app/trace.py", line 385, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/celery/app/trace.py", line 650, in __protected_call__
    return self.run(*args, **kwargs)
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/admin.py", line 62, in reset_db_task
    store_playlist_and_subobjects_to_db(user_spotify_id, playlist_spotify_id, spotify)
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/admin.py", line 137, in store_playlist_and_subobjects_to_db
    playlist_snapshot_id  = lookup_playlist(playlist_spotify_id, fields=['snapshot_id'])['snapshot_id']
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/util.py", line 65, in lookup_playlist
    spotify = init_spotipy()
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/util.py", line 13, in init_spotipy
    app_token = request_client_token(spotify_client_id, spotify_client_secret)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/util/credentials.py", line 59, in request_client_token
    return cred.request_client_token()
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/auth/refreshing.py", line 108, in request_client_token
    token = self._client.request_client_token()
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/auth/expiring.py", line 126, in wrapper
    response = self._send(request)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/sender.py", line 547, in _send
    return self.sender.send(request)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/sender.py", line 163, in send
    return sess.send(prepared, **self.requests_kwargs)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/requests/adapters.py", line 516, in send
    raise ConnectionError(e, request=request)
requests.exceptions.ConnectionError: HTTPSConnectionPool(host='accounts.spotify.com', port=443): Max retries exceeded with url: /api/token (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7febcff0cc88>: Failed to establish a new connection: [Errno 101] Network is unreachable'))
alexpogue commented 3 years ago

Although there's probably an elegant way to add it into Tekore itself if you think that makes sense, my solution was to write this into my own code.

def init_spotipy():
    spotify_client_id = app.config['SPOTIFY_CLIENT_ID']
    spotify_client_secret = app.config['SPOTIFY_CLIENT_SECRET']

    app_token = None
    retry_count = 0
    retry_limit = 10
    delay_seconds = 1

    while app_token is None and retry_count < retry_limit:
        try:
            app_token = request_client_token(spotify_client_id, spotify_client_secret)
        except:
            e = sys.exc_info()[0]
            app.logger.info('Caught exception {}, retry_count = {}, retry_limit = {}'.format(e, retry_count, retry_limit))
            if retry_count >= retry_limit:
                app.logger.error('Failed to get app token after retrying {} times. Reraising exception.'.format(retry_count))
                raise
            app_token = None
            retry_count += 1
            time.sleep(delay_seconds)
            delay_seconds *= 2

    # use RetryingSender to retry when we are rate limited by spotify API
    sender = RetryingSender(retries=100)
    return Spotify(app_token, sender=sender)

Since I wrote this, the resolution has caught many of these exceptions which tend to resolve on the first retry.

Also you probably notice that this is pretty shabby job - I blindly catch all exception types, and do nothing with any HTTP return codes.

felix-hilden commented 3 years ago

Hi and thank you for the kind words! You're still on Requests, huh? 😅 Actually, I'm seeing the same error as in the other issue you posted, which is HTTPX: #255. So are they related or did you just upgrade?

Anyway, both HTTPX ConnectError and Requests ConnectionError aren't based on a status code. They're raised way before any server could respond, so I think as you suggested in the other issue the solution is not to handle new codes but directly the error itself. Now in terms of extending Tekore's functionality, you're right that there is a reason for the retrying sender to handle only 429 and 5xx: they are the only non-user errors documented by the Web API. But I'm not against handling other errors! But there might be a way of having this with minimal effort, since (A)SyncSender accepts a HTTPX Client in the argument. See HTTPX docs on custom transports. It would go something like this:

trans = httpx.HTTPTransport(retries=1)
client = httpx.Client(transport=trans)

sender = tk.SyncSender(client=client)  # Or have an outer retrying sender or whatever
client = tk.Spotify(sender=sender)  # You know the drill here already

But regardless of what happens, this could be very valuable info in the documentation! Let me get back to you.

felix-hilden commented 3 years ago

I linked this issue to a documentation update. Let me know if the transport method works for you!

alexpogue commented 3 years ago

Hmm, I changed the code as suggested (code below), and I saw a tekore.ServiceUnavailable exception come up when RefreshingToken does request_client_token. I'm not sure if it does this every time, or if it only happens occasionally, but I have seen this pattern twice so far.

I dipped into tekore code to see where this error comes from, and found that it appears to comes from a 503 http response. I assumed this would be one of the cases where RetryingSender would retry the request, but I don't believe that is happening - the stack trace logs below show very little time elapsed between the previous log message and the stack trace, and if it were retrying I'd think we'd see more time between those log messages since tekore sleeps between retries.

My code in the https://github.com/felix-hilden/tekore/issues/254#issuecomment-858123708 would blindly swallow this exception and retry, but we are looking for a more elegant solution.

I'm sure it's something silly I'm doing wrong, but I can't really make sense of it.

Thanks for your help!

def init_spotipy():
    spotify_client_id = app.config['SPOTIFY_CLIENT_ID']
    spotify_client_secret = app.config['SPOTIFY_CLIENT_SECRET']

    app_token = request_client_token(spotify_client_id, spotify_client_secret)

    # Use transport that retries on httpx exception such as `httpx.ConnectError: [Errno 101] Network is unreachable`
    retrying_transport = httpx.HTTPTransport(retries=10)

    # increase the timeout to prevent spotify timeouts
    big_timeout_client = httpx.Client(timeout=60.0, transport=retrying_transport)
    big_timeout_sender = SyncSender(client=big_timeout_client)

    # use RetryingSender to retry when we are rate limited by spotify API
    sender = RetryingSender(retries=10, sender=big_timeout_sender)
    return Spotify(app_token, sender=sender)

Stack trace logs:

[2021-06-11 23:17:41,583: INFO/ForkPoolWorker-2] found playlist already in playlist, but not up to date - updating: 7nbvA0gXNZlLsrheFsWbDe
[2021-06-11 23:17:41,675: ERROR/ForkPoolWorker-2] Task playlist_search.routes.admin.reset_db_task[2eb02b8d-6a53-4630-8341-4fda51c942fe] raised unexpected: ServiceUnavailable('Unexpected error!')
Traceback (most recent call last):
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/celery/app/trace.py", line 385, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/celery/app/trace.py", line 650, in __protected_call__
    return self.run(*args, **kwargs)
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/admin.py", line 70, in reset_db_task
    store_playlist_and_subobjects_to_db(user_spotify_id, playlist_spotify_id, spotify)
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/admin.py", line 154, in store_playlist_and_subobjects_to_db
    playlist_snapshot_id  = lookup_playlist(playlist_spotify_id, fields=['snapshot_id'])['snapshot_id']
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/util.py", line 73, in lookup_playlist
    spotify = init_spotipy()
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/util.py", line 14, in init_spotipy
    app_token = request_client_token(spotify_client_id, spotify_client_secret)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_auth/util.py", line 204, in request_client_token
    return cred.request_client_token()
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_auth/refreshing.py", line 148, in request_client_token
    token = self._client.request_client_token()
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_sender/client.py", line 79, in wrapper
    return post_func(request, response, *params)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_auth/expiring/decor.py", line 29, in func
    handle_errors(request, response)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_auth/expiring/decor.py", line 22, in handle_errors
    raise error_cls(error_str, request=request, response=response)
tekore.ServiceUnavailable: Unexpected error!
alexpogue commented 3 years ago

I also just got an httpx.ConnectError: [Errno 101] Network is unreachable.. Timestamp shows a little more time elapsing though, so maybe httpx is doing some retries? I'm not sure.

[2021-06-11 23:52:39,598: INFO/ForkPoolWorker-2] found playlist already in playlist, but not up to date - updating: 3Nv71S5jUQJuIiIew8f7eb
[2021-06-11 23:52:44,743: ERROR/ForkPoolWorker-2] Task playlist_search.routes.admin.reset_db_task[a73e4da9-ed6b-4d52-9bb1-9242535baa0e] raised unexpected: ConnectError('[Errno 101] Network is unreachable')
Traceback (most recent call last):
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/celery/app/trace.py", line 385, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/celery/app/trace.py", line 650, in __protected_call__
    return self.run(*args, **kwargs)
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/admin.py", line 70, in reset_db_task
    store_playlist_and_subobjects_to_db(user_spotify_id, playlist_spotify_id, spotify)
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/admin.py", line 154, in store_playlist_and_subobjects_to_db
    playlist_snapshot_id  = lookup_playlist(playlist_spotify_id, fields=['snapshot_id'])['snapshot_id']
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/util.py", line 73, in lookup_playlist
    spotify = init_spotipy()
  File "/home/bandbldr/git/playlist_search/playlist_search/routes/util.py", line 14, in init_spotipy
    app_token = request_client_token(spotify_client_id, spotify_client_secret)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_auth/util.py", line 204, in request_client_token
    return cred.request_client_token()
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_auth/refreshing.py", line 148, in request_client_token
    token = self._client.request_client_token()
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_sender/client.py", line 78, in wrapper
    response = self.send(request)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_sender/client.py", line 47, in send
    return self.sender.send(request)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/tekore/_sender/concrete.py", line 41, in send
    data=request.data,
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/httpx/_client.py", line 729, in request
    request, auth=auth, allow_redirects=allow_redirects, timeout=timeout
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/httpx/_client.py", line 767, in send
    history=[],
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/httpx/_client.py", line 804, in _send_handling_auth
    history=history,
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/httpx/_client.py", line 832, in _send_handling_redirects
    response = self._send_single_request(request, timeout)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/httpx/_client.py", line 861, in _send_single_request
    ext={"timeout": timeout.as_dict()},
  File "/root/.pyenv/versions/3.7.1/lib/python3.7/contextlib.py", line 130, in __exit__
    self.gen.throw(type, value, traceback)
  File "/root/.local/share/virtualenvs/playlist_search-nA2ynR0j/lib/python3.7/site-packages/httpx/_exceptions.py", line 343, in map_exceptions
    raise mapped_exc(message, **kwargs) from exc  # type: ignore
httpx.ConnectError: [Errno 101] Network is unreachable
felix-hilden commented 3 years ago

In both cases this happens in request_client_token, which is not operated with any retries! If you want to have it, please instantiate a proper credentials class. Let me know how it goes!

felix-hilden commented 3 years ago

I've now updated the documentation, so I'll close this issue as well. Feel free to comment again though if you think that the proposed solution isn't enough!