Refresh token not used to get new token

[kummerer94]

Hey everyone,

first: great work on the library! I find the API to be awesome and working with it has been intuitive so far. The examples are well selected.

I ran into the following problem these days: I am using the device flow authentication and after one hour my token expires and is not automatically renewed. I know that the token is not renewed because when I send a request to the Microsoft Graph I get back that my token has expired.) When I debugged the code a little bit, I noticed the following problem:

In application.py, the force_refresh flag is not pulled into the _acquire_token_silent method and therefore it is ignored. The way i see it, you would need to change line 358 to

result = self._acquire_token_silent(scopes, account, self.authority, force_refresh, **kwargs)

The same is true for line 366, where this is also missing.

However, what I was unable to confirm is whether this fixes my original issue with the token that is not renewed but expires.

What would be helpful to me at this point would be some guidance on how to debug this problem and whether my observation that there is some bug in the force_refresh logic is true.

Best
Alexander

[rayluo]

Thanks for the encouraging feedback, @kummerer94 !

That force_refresh is a red herring in this case. The refresh is supposed to happen even without the force_refresh behavior. In fact, you wouldn't want to do force_refresh all the time, because that would defeat the purpose of a token cache.

How is your app's code organized? Assuming you are following our sample, did you also include this line? Was it reached in your code path? That sounds like NOT the case when you said:

"after one hour my token expires and is not automatically renewed".

You are supposed to trigger that acquire_token_silent() part each time you plan to use a token, only that way our token cache can have a chance to do the magic for you. If you get the first AccessToken which is only good for one hour and then you leave us, our acquire_token_silent() would NOT be able to do its job.

Please let us know. We are here to help!

[kummerer94]

Thanks for the quick answer, Ray!

My code basically follows this pattern:

# Initiate the app as a PublicClientApplication
app =msal.PublicClientApplication(...)
result = None

if not result:
    logging.info("No suitable token exists in cache. Let's get a new one from AAD.")
    flow = app.initiate_device_flow(scopes=resource)
    print(flow["message"])
    result = app.acquire_token_by_device_flow(flow)  # By default it will block

if "access_token" in result:
    accounts = app.get_accounts()
    if accounts:
        # I only have on account, so just choose this one all the time
        chosen = accounts[0]

    while True:
        token = app.acquire_token_silent(scopes=resource, account=chosen)
        # Do something periodically here using the token we just acquired
        time.sleep(10)

The problem with debugging this effectively is that I have to wait 60 minutes for the token to actually expire. That is the reason I was trying to use the force_refresh flag: to trigger the refresh manually and not wait for the token to expire. However, I did look into your code, especially the refresh part and since I am enabling the info level for the logging, I would expect to see the logging messages you are writing out there. However, every time I actually ran this code for longer than 60 minutes, I did not see anything of that sort in the logs.

[rayluo]

Thanks for your detail info. We will look into this soon (it is now Sunday in USA).

A quick comments though. If you are "enabling the INFO level for the logging", you won't see that refresh DEBUG log even when it actually happens.

[kummerer94]

Please, take your time. In no way I would expect any kind of response on a weekend. I just felt like answering this.

Of course you are right. I got my debug levels confused. I will let it run with the DEBUG level and see if there is any message.

[kummerer94]

Just as a quick update: I ran it again with the DEBUG level for the logs and it still seems like the refresh is never triggered inside the code. I do not see any logging message but trying to access the Microsoft Graph is returning the "Access token is expired" error.

[rayluo]

We tried, but could not reproduce the issue. Yet we are still willing to help.

Now in order to narrow down the test variations, would you please use the out-of-box device flow sample, wraps its major part inside your hour-long for-loop, redo your test, and see if you can observe the same logs as below?

When the previous access token was still valid, this line will show up in debug log:

DEBUG:msal.application:Cache hit an AT

When that access token is expired, these lines will show up in debug log:

DEBUG:msal.application:Found 1 RTs matching {'environment': 'login.microsoftonline.com', 'home_account_id': 'aa905949-a2b8-4e0a-8aea-????????.72f988bf-86f1-41af-91ab-????????', 'client_id': '????????'}
DEBUG:msal.application:Cache attempts an RT
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): login.microsoftonline.com:443
DEBUG:urllib3.connectionpool:https://login.microsoftonline.com:443 "POST /organizations/oauth2/v2.0/token HTTP/1.1" 200 4587
DEBUG:msal.token_cache:event={
...

One thing confuses me is that you said "I do not see any logging message", but you should at least see "Found 0 RTs matching {...}". Furthermore, if acquire_token_silent() really could not find any token, it would simply return None. But then how would you still have a token for you to "but trying to access the Microsoft Graph is returning the "Access token is expired" error"? It sounds like you somehow persist that short-live access token and reuse it, without really calling the acquire_token_silent() frequently. I would like to be proved that I were wrong here.

Lastly, you can consider use this adjustment to persist token cache on disk. That way you can later manually modify the "expires_on" value of an access token during debugging, so that you don't need to wait 1 hour per test.

[kummerer94]

Ray, I think I found the problem on my side. I finally figured it out after I took your advice and configured the persistent token cache. The problem was as you said that the token in my code was not updated even though I did retrieve a new one with the acquire_token_silent() method. Due to some programming error on my side, this new token never made it into the request but instead the old one was taken... my misconfiguration of the logging added to my confusion as I did not see any log that actually indicated a RT being used. Still, I think I understand OAuth now better than ever.

I am deeply sorry for the time you had to invest. I hope some day I can make it up to you.

[rayluo]

@kummerer94 Glad to hear the happy ending! Hooray!

Also, since you now know how to persist the token cache, please consier to reorganize your earlier code snippet to follow our sample, which can pick up a token from persisted cache, so that your script won't even need to actually do a device flow at every run.

Lastly, you don't need to "make it up" for me/us. Just tell everyone you know that Microsoft Identity service and its MSAL library are great, so you and your friends can count on it to build your next great project to benefit the world! :-)