Expired OAuth token refreshing endless loop #1090

Tepe · 2022-05-30T13:54:14Z

OAuth token refresh is not working properly. It keeps looping with 100% CPU load and creates million lines of debug output in a short time. It seems to get new session number but access_token itself stays as same and therefore keeps trying to refresh it again and again.

To reproduce you need to have an session which takes longer than OAuth expire time lasts (1 hour, e.g. big mailbox export).

MS documentation of the token refresh:
https://docs.microsoft.com/en-us/azure/active-directory/develop/v2-oauth2-auth-code-flow#refresh-the-access-token

DEBUG LOG:

<..returning from the job when token was not expired yet..>
INFO:exchangelib.fields:Found naive datetime 2021-01-25 10:53:31 on field last_modified_time. Assuming timezone Europe/Helsinki
DEBUG:exchangelib.services.common:Processing chunk 146 containing 30 items
DEBUG:exchangelib.services.common:Calling service GetItem
DEBUG:exchangelib.services.common:Trying API version Exchange2016
DEBUG:exchangelib.protocol:Server outlook.office365.com: Got session immediately
DEBUG:exchangelib.protocol:Server outlook.office365.com: Got session 87246
DEBUG:exchangelib.util:Session 87246 thread 139712341780288: retry 0 timeout 120 POST'ing to https://outlook.office365.com/EWS/Exchange.asmx after 10s wait
DEBUG:requests_oauthlib.oauth2_session:Invoking 0 protected resource request hooks.
DEBUG:requests_oauthlib.oauth2_session:Adding token {'token_type': 'Bearer', 'expires_in': 3599, 'ext_expires_in': 3599, 'access_token': 'eyJ0e <REMOVED> N9uGA', 'expires_at': 1653914631
.8988214} to request.
DEBUG:exchangelib.util:Session 87246 thread 139712341780288: OAuth token expired; refreshing
DEBUG:exchangelib.util:Retry: 0
Waited: 10
Timeout: 120
Session: 87246
Thread: 139712341780288
Auth type: <requests_oauthlib.oauth2_auth.OAuth2 object at 0x7f114de7d670>
URL: https://outlook.office365.com/EWS/Exchange.asmx
HTTP adapter: <requests.adapters.HTTPAdapter object at 0x7f114de7d580>
Allow redirects: False
Streaming: False
Response time: 0.0001604610006324947
Status code: 401
Request headers: {'X-AnchorMailbox': 'email@example.<REMOVED>'}
Response headers: {'TokenExpiredError': TokenExpiredError('(token_expired) ')}
DEBUG:exchangelib.util.xml:Request XML: b'<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<s:Envelope <REMOVED> </s:Envelope>'
Response XML: b''
DEBUG:exchangelib.protocol:Server outlook.office365.com: Renewing session 87246
DEBUG:exchangelib.protocol:Server outlook.office365.com: Created session 17831
DEBUG:exchangelib.util:Session 17831 thread 139712341780288: retry 0 timeout 120 POST'ing to https://outlook.office365.com/EWS/Exchange.asmx after 10s wait
DEBUG:requests_oauthlib.oauth2_session:Invoking 0 protected resource request hooks.
DEBUG:requests_oauthlib.oauth2_session:Adding token {'token_type': 'Bearer', 'expires_in': 3599, 'ext_expires_in': 3599, 'access_token': 'eyJ0e <REMOVED> N9uGA', 'expires_at': 1653914631
.8988214} to request.
DEBUG:exchangelib.util:Session 17831 thread 139712341780288: OAuth token expired; refreshing
DEBUG:exchangelib.util:Retry: 0
Waited: 10
Timeout: 120
Session: 17831
Thread: 139712341780288
Auth type: <requests_oauthlib.oauth2_auth.OAuth2 object at 0x7f114de7d670>
URL: https://outlook.office365.com/EWS/Exchange.asmx
HTTP adapter: <requests.adapters.HTTPAdapter object at 0x7f114de7d580>
Allow redirects: False
Streaming: False
Response time: 0.0004302969991840655
Status code: 401
Request headers: {'X-AnchorMailbox': 'email@example.<REMOVED>'}
Response headers: {'TokenExpiredError': TokenExpiredError('(token_expired) ')}
DEBUG:exchangelib.util.xml:Request XML: b'<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<s:Envelope <REMOVED></s:Envelope>'
Response XML: b''
DEBUG:exchangelib.protocol:Server outlook.office365.com: Renewing session 17831
DEBUG:exchangelib.protocol:Server outlook.office365.com: Created session 43264
DEBUG:exchangelib.util:Session 43264 thread 139712341780288: retry 0 timeout 120 POST'ing to https://outlook.office365.com/EWS/Exchange.asmx after 10s wait
DEBUG:requests_oauthlib.oauth2_session:Invoking 0 protected resource request hooks.
DEBUG:requests_oauthlib.oauth2_session:Adding token {'token_type': 'Bearer', 'expires_in': 3599, 'ext_expires_in': 3599, 'access_token': 'eyJ0 <REMOVED> N9uGA', 'expires_at': 1653914631
.8988214} to request.
DEBUG:exchangelib.util:Session 43264 thread 139712341780288: OAuth token expired; refreshing
DEBUG:exchangelib.util:Retry: 0
Waited: 10
Timeout: 120
Session: 43264
Thread: 139712341780288
Auth type: <requests_oauthlib.oauth2_auth.OAuth2 object at 0x7f114de7d670>
URL: https://outlook.office365.com/EWS/Exchange.asmx
HTTP adapter: <requests.adapters.HTTPAdapter object at 0x7f114de7d580>
Allow redirects: False
Streaming: False

VERSIONS:
Python 3.9.10
exchangelib 4.7.3

The text was updated successfully, but these errors were encountered:

cmin764 · 2022-07-06T09:02:26Z

I solved it with a monkey patch like so:

import functools

from exchangelib.services import common as exchangelib_common
from exchangelib.util import post_ratelimited


def extended_post_ratelimited(protocol, session, *args, **kwargs):
    session.post = functools.partial(
        session.post,
        client_id=protocol.credentials.client_id,
        client_secret=protocol.credentials.client_secret,
    )
    return post_ratelimited(protocol, session, *args, **kwargs)

# Monkey-patching infinite loop fix on token refresh, due to OAuth2 library bug when
#  passing the app credentials to the "/token" endpoint.
exchangelib_common.post_ratelimited = extended_post_ratelimited

While the client credentials are sent correctly as observed in the library's procotol.py:

session_params.update(
                    {
                        "auto_refresh_kwargs": {
                            "client_id": self.credentials.client_id,
                            "client_secret": self.credentials.client_secret,
                        },
                        "auto_refresh_url": token_url,
                        "token_updater": self.credentials.on_token_auto_refreshed,
                    }
                )

during refresh they are encoded in the body sent in the /token POST request but they aren't read by the server, thus explicitly injecting them in the common posting utility unblocked me here.

It might be a problem outside of this library, actually inside requests-oauthlib under oauth2_session.OAuth2Session.refresh_token when this happens:

kwargs.update(self.auto_refresh_kwargs)
body = self._client.prepare_refresh_body(
        body=body, refresh_token=refresh_token, scope=self.scope, **kwargs
)

place where the body (which contains the client creds) isn't in the right shape for the Exchange Online server. (as it works if auth object is provided with the client creds)

Reported it here as well, but this might go further into oauthlib.oauth2.rfc6749.parameters.prepare_token_request where the client_id & client_secret params are only added to the query string with add_params_to_qs(body, params) and that might not be sufficient.

ecederstrand · 2022-07-13T12:59:18Z

Thanks for the detailed write-up! Let's wait to see if the requests-oauthlib issue gets any responses. Otherwise, we can have a look at patches to exchangelib.

…work around token refresh bug. Fixes #1090

ecederstrand · 2022-08-05T10:00:01Z

@cmin764 and @Tepe

It seems the upstream issue is not getting any attention. I came up with a slightly different patch in #1104. I'm unable to properly test because I don't have access to a setup that uses OAuth2AuthorizationCodeCredentials. Can you give it a spin before I merge the PR?

… configurable. Fixes #1102

Tepe · 2022-08-05T10:15:09Z

@cmin764 and @Tepe

It seems the upstream issue is not getting any attention. I came up with a slightly different patch in https://github.com/ecederstrand/exchangelib/pull/1104/files. I'm unable to properly test because I don't have access to a setup that uses OAuth2AuthorizationCodeCredentials. Can you give it a spin before I merge the PR?

Sure, I'll test it with that patched util.py and report back how it goes.

Tepe · 2022-08-05T11:59:32Z

Seems to end up on looping with that patch as well. Exact behavior.
Had no debug logging on as it fills up disk so fast while looping, but CPU usage was 100% (normally 15-40% while transfer) and transferred items did hang on 4350 of 13852 which is around 4GB of data.

>> 13852/4350^C.Traceback (most recent call last):
  File "/home/backup-test/butest.py", line 159, in <module>
    for item in qs:
  File "/home/backup-test/exchangelib/queryset.py", line 273, in __iter__
    yield from self._format_items(items=self._query(), return_format=self.return_format)
  File "/home/backup-test/exchangelib/queryset.py", line 348, in _item_yielder
    for i in iterable:
  File "/home/backup-test/exchangelib/account.py", line 719, in fetch
    yield from self._consume_item_service(
  File "/home/backup-test/exchangelib/account.py", line 414, in _consume_item_service
    yield from service_cls(account=self, chunk_size=chunk_size).call(**kwargs)
  File "/home/backup-test/exchangelib/services/common.py", line 187, in _elems_to_objs
    for elem in elems:
  File "/home/backup-test/exchangelib/services/common.py", line 243, in _chunked_get_elements
    for i, chunk in enumerate(chunkify(filtered_items, self.chunk_size), start=1):
  File "/home/backup-test/exchangelib/util.py", line 130, in chunkify
    for i in iterable:
  File "/home/backup-test/exchangelib/folders/collections.py", line 211, in find_items
    yield from FindItem(account=self.account, page_size=page_size).call(
  File "/home/backup-test/exchangelib/services/common.py", line 187, in _elems_to_objs
    for elem in elems:
  File "/home/backup-test/exchangelib/services/common.py", line 741, in _paged_call
    pages = self._get_pages(payload_func, kwargs, len(paging_infos))
  File "/home/backup-test/exchangelib/services/common.py", line 838, in _get_pages
    page_elems = list(self._get_elements(payload=payload))
  File "/home/backup-test/exchangelib/services/common.py", line 265, in _get_elements
    yield from self._response_generator(payload=payload)
  File "/home/backup-test/exchangelib/services/common.py", line 227, in _response_generator
    response = self._get_response_xml(payload=payload)
  File "/home/backup-test/exchangelib/services/common.py", line 343, in _get_response_xml
    r = self._get_response(payload=payload, api_version=api_version)
  File "/home/backup-test/exchangelib/services/common.py", line 297, in _get_response
    r, session = post_ratelimited(
  File "/home/backup-test/exchangelib/util.py", line 864, in post_ratelimited
    log_vals.update(
KeyboardInterrupt

ecederstrand · 2022-08-05T12:06:33Z

Does the same happen with the monkey patch from @cmin764 ?

In addition to this issue, you may be hitting a possible memory leak. You can try my suggestion in #1100 (comment) which might be a workaround.

Tepe · 2022-08-05T12:11:57Z

I will test that memory leak workaround and if it's not working then the monkey patch.

Memory leak workaround didn't help:

Itemcount: 13852
>> 13852/4800^C.Traceback (most recent call last):
  File "/home/backup-test/butest.py", line 161, in <module>
    for item in qs:
  File "/home/backup-test/exchangelib/queryset.py", line 273, in __iter__
    yield from self._format_items(items=self._query(), return_format=self.return_format)
  File "/home/backup-test/exchangelib/queryset.py", line 348, in _item_yielder
    for i in iterable:
  File "/home/backup-test/exchangelib/account.py", line 719, in fetch
    yield from self._consume_item_service(
  File "/home/backup-test/exchangelib/account.py", line 414, in _consume_item_service
    yield from service_cls(account=self, chunk_size=chunk_size).call(**kwargs)
  File "/home/backup-test/exchangelib/services/common.py", line 187, in _elems_to_objs
    for elem in elems:
  File "/home/backup-test/exchangelib/services/common.py", line 243, in _chunked_get_elements
    for i, chunk in enumerate(chunkify(filtered_items, self.chunk_size), start=1):
  File "/home/backup-test/exchangelib/util.py", line 130, in chunkify
    for i in iterable:
  File "/home/backup-test/exchangelib/folders/collections.py", line 211, in find_items
    yield from FindItem(account=self.account, page_size=page_size).call(
  File "/home/backup-test/exchangelib/services/common.py", line 187, in _elems_to_objs
    for elem in elems:
  File "/home/backup-test/exchangelib/services/common.py", line 741, in _paged_call
    pages = self._get_pages(payload_func, kwargs, len(paging_infos))
  File "/home/backup-test/exchangelib/services/common.py", line 838, in _get_pages
    page_elems = list(self._get_elements(payload=payload))
  File "/home/backup-test/exchangelib/services/common.py", line 265, in _get_elements
    yield from self._response_generator(payload=payload)
  File "/home/backup-test/exchangelib/services/common.py", line 227, in _response_generator
    response = self._get_response_xml(payload=payload)
  File "/home/backup-test/exchangelib/services/common.py", line 343, in _get_response_xml
    r = self._get_response(payload=payload, api_version=api_version)
  File "/home/backup-test/exchangelib/services/common.py", line 297, in _get_response
    r, session = post_ratelimited(
  File "/home/backup-test/exchangelib/util.py", line 882, in post_ratelimited
    session = protocol.refresh_credentials(session)
  File "/home/backup-test/exchangelib/protocol.py", line 277, in refresh_credentials
    return self.renew_session(session)
  File "/home/backup-test/exchangelib/protocol.py", line 263, in renew_session
    return self.create_session()
  File "/home/backup-test/exchangelib/protocol.py", line 288, in create_session
    session = self.create_oauth2_session()
  File "/home/backup-test/exchangelib/protocol.py", line 350, in create_oauth2_session
    session = self.raw_session(self.service_endpoint, oauth2_client=client, oauth2_session_params=session_params)
  File "/home/backup-test/exchangelib/protocol.py", line 371, in raw_session
    session = OAuth2Session(client=oauth2_client, **(oauth2_session_params or {}))
  File "/home/backup-test/.local/lib/python3.9/site-packages/requests_oauthlib/oauth2_session.py", line 77, in __init__
    super(OAuth2Session, self).__init__(**kwargs)
  File "/usr/lib/python3.9/site-packages/requests/sessions.py", line 422, in __init__
    self.mount('http://', HTTPAdapter())
  File "/usr/lib/python3.9/site-packages/requests/adapters.py", line 117, in __init__
    self.max_retries = Retry(0, read=False)
  File "/usr/lib/python3.9/site-packages/urllib3/util/retry.py", line 279, in __init__
    self.raise_on_status = raise_on_status
KeyboardInterrupt

Tepe · 2022-08-05T19:14:39Z

I wasn't able to get monkey patch working. Same issue, in endless loop.

Tepe · 2022-08-06T13:25:09Z

@ecederstrand
I checked the code and noticed that it might not clear expired token when renewing the session?
It pulls token from credentials and passes it as an parameter when requesting new session?
Did add token sanitation into the renew_session.
I don't know if this is the best or correct place/way to do it, but at least it's working now and without f7af5d9 / monkey patch.

Btw I am using BackendApplicationClient, not WebApplicationClient on these tests, which might handle token refresh differently (not using refreshtoken, instead requests completely new one with the new session).

    def renew_session(self, session):
        # The session is useless. Close it completely and place a fresh session in the pool
        log.debug("Server %s: Renewing session %s", self.server, session.session_id)
        self.credentials.access_token=None
        self.close_session(session)
        return self.create_session()

I managed to pull full mailbox including 24614 items in several gigabytes.
System used had only 2GB memory and didn't notice any memory leaks even session was set to unlimited usage count.

PS. Issue closed by misclick

…ken. Refs #1090

ecederstrand · 2022-08-08T12:39:12Z

Thanks for the find and for testing! I believe #1105 would be a more correct fix. Can you give it a spin before I merge?

Refs #1090

cmin764 · 2022-08-09T08:02:42Z

@ecederstrand 🎉 I just gave it a try and it works now flawlessly, thank you!

Here's how I tested:

Removed our monkey-patch, used an expired token, ended up in the endless loop.
Added your patch and ran the robot from the local venv: RPA_WORKITEMS_ADAPTER=RPA.Robocorp.WorkItems.FileAdapter RPA_INPUT_WORKITEM_PATH=devdata/work-items-in/microsoft/work-items.json RPA_SECRET_MANAGER=RPA.Robocorp.Vault.FileSecrets RPA_SECRET_FILE=~/Secrets/example-oauth-email.yaml python -m robot -L TRACE -d ./output --task "Send Microsoft Email" tasks.robot
Got the token refreshed in my local example-oauth-email.yaml secrets file.

So that patch works, maybe @Tepe has a different use-case where the other change (with session cleanup) is required too. Please let me know about the library version as soon as you release so we can refactor our bot. Thx!

ecederstrand · 2022-08-09T08:16:26Z

Thanks for the feedback! Version 4.7.5 is out now.

cmin764 · 2022-08-09T11:56:35Z

Thanks for the feedback! Version 4.7.5 is out now.

@ecederstrand Thank you! Tested with it and it doesn't work since I made a terrible confusion between the PR comments, exactly the other one was the one fixing the problem: #1104

…around token refresh bug (#1106) Fixes #1090

cmin764 · 2022-08-09T14:59:19Z

Thank you! Would a 4.7.6 be out soon?

ecederstrand · 2022-08-10T05:35:08Z

It's out now.

cmin764 · 2022-08-10T08:18:25Z

It's out now.

Thank you @ecederstrand , although I can't see any such release yet:

% pip install -U exchangelib==4.7.6
ERROR: Could not find a version that satisfies the requirement exchangelib==4.7.6 (from versions: 1.2, 1.3, 1.3.1, 1.3.2, 1.3.3, 1.3.4, 1.3.5, 1.3.6, 1.3.7, 1.4, 1.4.1, 1.4.2, 1.5.0, 1.5.2, 1.6.0, 1.6.1, 1.6.2, 1.7.0, 1.7.1, 1.7.2, 1.7.3, 1.7.4, 1.7.5, 1.7.6, 1.8.0, 1.8.1, 1.9.0, 1.9.1, 1.9.2, 1.9.3, 1.9.4, 1.9.5, 1.9.6, 1.10.0, 1.10.1, 1.10.2, 1.10.3, 1.10.4, 1.10.5, 1.10.6, 1.10.7, 1.11.0, 1.11.1, 1.11.2, 1.11.3, 1.11.4, 1.12.0, 1.12.1, 1.12.2, 1.12.3, 1.12.4, 1.12.5, 2.0.0, 2.0.1, 2.1.0, 2.1.1, 2.2.0, 3.0.0, 3.1.0, 3.1.1, 3.2.0, 3.2.1, 3.3.0, 3.3.1, 3.3.2, 4.0.0, 4.1.0, 4.2.0, 4.3.0, 4.4.0, 4.5.0, 4.5.1, 4.5.2, 4.6.0, 4.6.1, 4.6.2, 4.7.0, 4.7.1, 4.7.2, 4.7.3, 4.7.4, 4.7.5)
ERROR: No matching distribution found for exchangelib==4.7.6

ecederstrand · 2022-08-10T08:22:10Z

It turns out you need to actually build the new package before uploading to PyPI. Otherwise you're just re-uploading 4.7.5 :-) It's there now.

cmin764 · 2022-08-10T14:45:20Z

🎉 Works flawlessly with 4.7.6. Thank you!

cmin764 mentioned this issue Jul 6, 2022

oauth2_session.OAuth2Session.refresh_token creates infinite loop with Exchange Online when token expires requests/requests-oauthlib#498

Open

ecederstrand added a commit that referenced this issue Aug 5, 2022

fix: Add client_id and client_secret explicitly to session.post() to …

f7af5d9

…work around token refresh bug. Fixes #1090

ecederstrand mentioned this issue Aug 5, 2022

Add workaround for upstream token refresh bug #1104

Closed

ecederstrand referenced this issue Aug 5, 2022

feat: make timeout and lifetime settings of DNS resolver individually…

5b6656d

… configurable. Fixes #1102

Tepe closed this as completed Aug 6, 2022

ecederstrand reopened this Aug 8, 2022

ecederstrand added a commit that referenced this issue Aug 8, 2022

fix: When a session is retired, make sure to also clear the access to…

ead6019

…ken. Refs #1090

ecederstrand mentioned this issue Aug 8, 2022

When a session is retired, make sure to also clear access token #1105

Merged

ecederstrand mentioned this issue Aug 8, 2022

Memory leak in long-running scripts when using OAuth #1100

Open

ecederstrand closed this as completed in #1105 Aug 9, 2022

ecederstrand added a commit that referenced this issue Aug 9, 2022

When a session is retired, make sure to also clear access token (#1105)

f73143c

Refs #1090

ecederstrand mentioned this issue Aug 9, 2022

Add client_id and client_secret explicitly to session.post() #1106

Merged

ecederstrand reopened this Aug 9, 2022

ecederstrand closed this as completed in #1106 Aug 9, 2022

ecederstrand added a commit that referenced this issue Aug 9, 2022

Add client_id and client_secret explicitly to session.post() to work …

2672ff9

…around token refresh bug (#1106) Fixes #1090

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Expired OAuth token refreshing endless loop #1090

Expired OAuth token refreshing endless loop #1090

Tepe commented May 30, 2022 •

edited

Loading

cmin764 commented Jul 6, 2022 •

edited

Loading

ecederstrand commented Jul 13, 2022 •

edited

Loading

ecederstrand commented Aug 5, 2022 •

edited

Loading

Tepe commented Aug 5, 2022 •

edited

Loading

Tepe commented Aug 5, 2022 •

edited

Loading

ecederstrand commented Aug 5, 2022

Tepe commented Aug 5, 2022 •

edited

Loading

Tepe commented Aug 5, 2022 •

edited

Loading

Tepe commented Aug 6, 2022 •

edited

Loading

ecederstrand commented Aug 8, 2022

cmin764 commented Aug 9, 2022

ecederstrand commented Aug 9, 2022

cmin764 commented Aug 9, 2022

cmin764 commented Aug 9, 2022

ecederstrand commented Aug 10, 2022

cmin764 commented Aug 10, 2022 •

edited

Loading

ecederstrand commented Aug 10, 2022

cmin764 commented Aug 10, 2022 •

edited

Loading

Expired OAuth token refreshing endless loop #1090

Expired OAuth token refreshing endless loop #1090

Comments

Tepe commented May 30, 2022 • edited Loading

cmin764 commented Jul 6, 2022 • edited Loading

ecederstrand commented Jul 13, 2022 • edited Loading

ecederstrand commented Aug 5, 2022 • edited Loading

Tepe commented Aug 5, 2022 • edited Loading

Tepe commented Aug 5, 2022 • edited Loading

ecederstrand commented Aug 5, 2022

Tepe commented Aug 5, 2022 • edited Loading

Tepe commented Aug 5, 2022 • edited Loading

Tepe commented Aug 6, 2022 • edited Loading

ecederstrand commented Aug 8, 2022

cmin764 commented Aug 9, 2022

ecederstrand commented Aug 9, 2022

cmin764 commented Aug 9, 2022

cmin764 commented Aug 9, 2022

ecederstrand commented Aug 10, 2022

cmin764 commented Aug 10, 2022 • edited Loading

ecederstrand commented Aug 10, 2022

cmin764 commented Aug 10, 2022 • edited Loading

Tepe commented May 30, 2022 •

edited

Loading

cmin764 commented Jul 6, 2022 •

edited

Loading

ecederstrand commented Jul 13, 2022 •

edited

Loading

ecederstrand commented Aug 5, 2022 •

edited

Loading

Tepe commented Aug 5, 2022 •

edited

Loading

Tepe commented Aug 5, 2022 •

edited

Loading

Tepe commented Aug 5, 2022 •

edited

Loading

Tepe commented Aug 5, 2022 •

edited

Loading

Tepe commented Aug 6, 2022 •

edited

Loading

cmin764 commented Aug 10, 2022 •

edited

Loading

cmin764 commented Aug 10, 2022 •

edited

Loading