Bug report: Refreshing access tokens broken by update (v7.5.0+?)

ToeKneeFan commented 1 week ago

Priority

(Urgent) I can't use the CLI

Description

After a recent update to v7.9.0, my instance of the m365 CLI fails to refresh access tokens. The API is accessed not through the standard PnP app but through a personal app registration in the Azure portal. This app registration requests the following scopes: email, Mail.Read, Mail.Read.Shared, Mail.ReadBasic, Mail.ReadBasic.Shared, Mail.ReadWrite, Mail.ReadWrite.Shared, Mail.Send, Mail.Send.Shared, offline_access, openid, profile, and User.Read.

After logging in with m365 login, the CLI (specifically, mail commands, like m365 outlook mail send) works for about an hour (the lifetime of the access token) and then fails to refresh the access token (attempting to use the CLI results in a request to log in: 🌶️ To sign in, use a web browser to open the page https://microsoft.com/devicelogin and enter the code <redacted> to authenticate).

Downgrading to v7.0.0 fixes this issue. To check for reproducibility, I upgraded and downgraded at least three times, testing whether the token refreshes, and v7.9.0 consistently fails to refresh the token, whereas v7.0.0 works well and a refreshed access token is still intact hours later.

Based on this, I speculate that the issue can be isolated to a change in the versions between v7.1.0 to v7.9.0 (inclusive), perhaps something related to the way that tokens are refreshed or the way the offline_access scope is handled.

I may be in a somewhat rare situation, since I am using a personal account without a dedicated tenant ("common") and with a custom app registration; I suspect that most people are using the m365 CLI within a corporate tenant, which may affect reproducibility of this bug.

Steps to reproduce

Install v7.9.0 of the m365 CLI.
Login with m365 login with a specified app ID from an app registration (with scopes email, Mail.Read, Mail.Read.Shared, Mail.ReadBasic, Mail.ReadBasic.Shared, Mail.ReadWrite, Mail.ReadWrite.Shared, Mail.Send, Mail.Send.Shared, offline_access, openid, profile, and User.Read) and the default DeviceCode flow (if applicable, using a personal account without a specified tenant). Specify --debug here or run m365 status --debug to get the expiration time afterward.
Wait until after the expiration of the access token, and attempt to use a CLI command (e.g., m365 outlook mail send).

Expected results

I would expect the command to work (namely, m365 outlook mail send should send an email)

Actual results

The m365 authentication is expired and requests another login. 🌶️ To sign in, use a web browser to open the page https://microsoft.com/devicelogin and enter the code <redacted> to authenticate

Diagnostics

Result of `m365 login`:

Executing command login with options {"options":{"debug":true,"appId":"<redacted>","output":"json"}}
Logging out from Microsoft 365...
Signing in to Microsoft 365...
No token found for resource https://graph.microsoft.com.
[Wed, 26 Jun 2024 23:36:33 GMT] : [] : @azure/msal-node@2.7.0 : Info - getTokenCache called
Starting Auth.ensureAccessTokenWithDeviceCode. resource: https://graph.microsoft.com, debug: true
[Wed, 26 Jun 2024 23:36:33 GMT] : [] : @azure/msal-node@2.7.0 : Info - acquireTokenByDeviceCode called
[Wed, 26 Jun 2024 23:36:33 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - initializeRequestScopes called
[Wed, 26 Jun 2024 23:36:33 GMT] : [<redacted>] : @azure/msal-node@2.7.0 : Verbose - buildOauthClientConfiguration called
[Wed, 26 Jun 2024 23:36:33 GMT] : [<redacted>] : @azure/msal-node@2.7.0 : Verbose - createAuthority called
[Wed, 26 Jun 2024 23:36:33 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Attempting to get cloud discovery metadata  from authority configuration
[Wed, 26 Jun 2024 23:36:33 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Did not find cloud discovery metadata in the config... Attempting to get cloud discovery metadata from the hardcoded values.
[Wed, 26 Jun 2024 23:36:33 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Found cloud discovery metadata from hardcoded values.
[Wed, 26 Jun 2024 23:36:33 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Attempting to get endpoint metadata from authority configuration
[Wed, 26 Jun 2024 23:36:33 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Did not find endpoint metadata in the config... Attempting to get endpoint metadata from the hardcoded values.
[Wed, 26 Jun 2024 23:36:33 GMT] : [<redacted>] : @azure/msal-node@2.7.0 : Info - Building oauth client configuration with the following authority: https://login.microsoftonline.com/common/oauth2/v2.0/token.
[Wed, 26 Jun 2024 23:36:33 GMT] : [<redacted>] : @azure/msal-node@2.7.0 : Verbose - Device code client created
Response:
{
  userCode: '<redacted>',
  deviceCode: '<redacted>',
  verificationUri: 'https://microsoft.com/devicelogin',
  expiresIn: 900,
  interval: 5,
  message: 'To sign in, use a web browser to open the page https://microsoft.com/devicelogin and enter the code <redacted> to authenticate.'
}

[Wed, 26 Jun 2024 23:36:34 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
[Wed, 26 Jun 2024 23:36:40 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
[Wed, 26 Jun 2024 23:36:45 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
[Wed, 26 Jun 2024 23:36:51 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
[Wed, 26 Jun 2024 23:36:57 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
[Wed, 26 Jun 2024 23:37:02 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
[Wed, 26 Jun 2024 23:37:08 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
[Wed, 26 Jun 2024 23:37:13 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
[Wed, 26 Jun 2024 23:37:19 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
[Wed, 26 Jun 2024 23:37:25 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Verbose - Authorization completed successfully. Polling stopped.
[Wed, 26 Jun 2024 23:37:25 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Verbose - setCachedAccount called
[Wed, 26 Jun 2024 23:37:25 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Verbose - Persistence enabled, calling beforeCacheAccess
[Wed, 26 Jun 2024 23:37:25 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Verbose - Persistence enabled, calling afterCacheAccess
Response
{
  authority: 'https://login.microsoftonline.com/common/',
  uniqueId: '<redacted>',
  tenantId: '<redacted>',
  scopes: [
    'https://graph.microsoft.com/.default',
    'openid',
    'profile',
    'https://graph.microsoft.com/Mail.Read',
    'https://graph.microsoft.com/Mail.ReadBasic',
    'https://graph.microsoft.com/Mail.ReadBasic.Shared',
    'https://graph.microsoft.com/Mail.ReadWrite',
    'https://graph.microsoft.com/Mail.Send',
    'https://graph.microsoft.com/User.Read'
  ],
  account: {
    homeAccountId: '<redacted>',
    environment: 'login.windows.net',
    tenantId: '<redacted>',
    username: '<redacted>',
    localAccountId: '<redacted>',
    name: '<redacted>',
    nativeAccountId: undefined,
    authorityType: 'MSSTS',
    tenantProfiles: Map(1) { '<redacted>' => [Object] },
    idTokenClaims: {
      ver: '2.0',
      iss: '<redacted>',
      sub: '<redacted>',
      aud: '<redacted>',
      exp: 1719531444,
      iat: 1719444744,
      nbf: 1719444744,
      name: '<redacted>',
      preferred_username: '<redacted>',
      oid: '<redacted>',
      tid: '<redacted>',
      aio: '<redacted>'
    },
    idToken: '<redacted>'
  },
  idToken: '<redacted>',
  idTokenClaims: {
    ver: '2.0',
    iss: '<redacted>',
    sub: '<redacted>',
    aud: '<redacted>',
    exp: 1719531444,
    iat: 1719444744,
    nbf: 1719444744,
    name: '<redacted>',
    preferred_username: '<redacted>',
    oid: '<redacted>',
    tid: '<redacted>',
    aio: '<redacted>'
  },
  accessToken: '<redacted>',
  fromCache: false,
  expiresOn: 2024-06-27T00:36:34.000Z,
  extExpiresOn: 2024-06-27T01:36:34.000Z,
  refreshOn: undefined,
  correlationId: <redacted>,
  requestId: '',
  familyId: '',
  tokenType: 'Bearer',
  state: '',
  cloudGraphHostName: '',
  msGraphHost: '',
  code: undefined,
  fromNativeBroker: false
}

{
  "connectionName": "",
  "connectedAs": "",
  "authType": "DeviceCode",
  "appId": <redacted>,
  "appTenant": "common",
  "cloudType": "Public",
  "accessToken": "{\\\n  \"https://graph.microsoft.com\": {\\\n    \"expiresOn\": \"2024-06-27T00:36:34.000Z\",\\\n    \"accessToken\": \"<redacted>\"\\\n  }\\\n}"
}
DONE

Timings:
api: 0ms
core: 22.835244ms
command: 52670.806827ms
options: 0.36838ms
total: 52699.246329ms
validation: 1.370589ms

Result of `m365 outlook mail send -s 'test' -t <redacted email> --bodyContents 'test' --debug`

Executing command outlook mail send with options {"options":{"debug":true,"subject":"test","to":"<redacted>","bodyContents":"test","output":"json"}}
Executing command as '', appId: <redacted>, tenantId:
Access token expired. Token: <redacted>, ExpiresAt: 2024-06-27T00:36:34.000Z
[Thu, 27 Jun 2024 00:39:24 GMT] : [] : @azure/msal-node@2.7.0 : Info - getTokenCache called
[Thu, 27 Jun 2024 00:39:24 GMT] : [] : @azure/msal-common@14.9.0 : Info - CacheManager:getIdToken - Returning ID token
Starting Auth.ensureAccessTokenWithDeviceCode. resource: https://graph.microsoft.com, debug: true
[Thu, 27 Jun 2024 00:39:24 GMT] : [] : @azure/msal-node@2.7.0 : Info - acquireTokenByDeviceCode called
[Thu, 27 Jun 2024 00:39:24 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - initializeRequestScopes called
[Thu, 27 Jun 2024 00:39:24 GMT] : [<redacted>] : @azure/msal-node@2.7.0 : Verbose - buildOauthClientConfiguration called
[Thu, 27 Jun 2024 00:39:24 GMT] : [<redacted>] : @azure/msal-node@2.7.0 : Verbose - createAuthority called
[Thu, 27 Jun 2024 00:39:24 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Attempting to get cloud discovery metadata  from authority configuration
[Thu, 27 Jun 2024 00:39:24 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Did not find cloud discovery metadata in the config... Attempting to get cloud discovery metadata from the hardcoded values.
[Thu, 27 Jun 2024 00:39:24 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Found cloud discovery metadata from hardcoded values.
[Thu, 27 Jun 2024 00:39:24 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Attempting to get endpoint metadata from authority configuration
[Thu, 27 Jun 2024 00:39:24 GMT] : [] : @azure/msal-node@2.7.0 : Verbose - Did not find endpoint metadata in the config... Attempting to get endpoint metadata from the hardcoded values.
[Thu, 27 Jun 2024 00:39:24 GMT] : [<redacted>] : @azure/msal-node@2.7.0 : Info - Building oauth client configuration with the following authority: https://login.microsoftonline.com/common/oauth2/v2.0/token.
[Thu, 27 Jun 2024 00:39:24 GMT] : [<redacted>] : @azure/msal-node@2.7.0 : Verbose - Device code client created
Response:
{
  userCode: '<redacted>',
  deviceCode: '<redacted>',
  verificationUri: 'https://microsoft.com/devicelogin',
  expiresIn: 900,
  interval: 5,
  message: 'To sign in, use a web browser to open the page https://microsoft.com/devicelogin and enter the code <redacted> to authenticate.'
}

[Thu, 27 Jun 2024 00:39:26 GMT] : [<redacted>] : @azure/msal-common@14.9.0 : Info - Authorization pending. Continue polling.
🌶️  To sign in, use a web browser to open the page https://microsoft.com/devicelogin and enter the code <redacted> to authenticate.

CLI for Microsoft 365 version

v7.9.0

nodejs version

v20.14.0

Operating system (environment)

Linux

Shell

bash

cli doctor

{
  "os": {
    "platform": "linux",
    "version": "#35~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Tue May  7 09:00:52 UTC 2",
    "release": "6.5.0-35-generic"
  },
  "cliVersion": "7.9.0",
  "nodeVersion": "v20.14.0",
  "cliAadAppId": "<redacted>",
  "cliAadAppTenant": "common",
  "authMode": "DeviceCode",
  "cliEnvironment": "",
  "cliConfig": {
    "disableTelemetry": true
  },
  "roles": [],
  "scopes": {}
}

Additional Info

No response

ToeKneeFan commented 1 week ago

This issue is perhaps most similar to #3942 (reporting a similar failure to refresh) but, based on the timeline, is unlikely to be rooted in the same problem (given v7.0.0 was published on npm on Oct 2, 2023 and #3942 was reported well before that on Oct 27, 2022).

ToeKneeFan commented 1 week ago

After further investigation, it appears this issue can be isolated to a change that occurred between v7.4.0 and v7.5.0. Refreshing access tokens (in the scenario described above with a personal account, custom app registration, etc.) works on v7.0.0–v7.4.0 and then begins to fail on v7.5.0.

Based on the release notes, I would tentatively speculate that this is related to "added support for signing in with multiple identities #3587," since other changes were generally related to more specific commands/subcommands, whereas #3587 was associated with more fundamental changes in the way logins and connections are handled.

milanholemans commented 1 week ago

Hi @ToeKneeFan, sorry to hear CLI is malfunctioning for you. I love to see the amount of context you are giving. This will help us a lot. In v7.5.0 we did introduce multiple connections indeed. However, I can't really see why this would cause issues. What strikes me the most is the fact that when you run m365 cli doctor, your scopes are completely empty. Have you checked the connection files on your user home directory?

ToeKneeFan commented 1 week ago

Thank you very much for following up, @milanholemans!

Both ".cli-m365-all-connections.json" and ".cli-m365-connection.json" have the following contents after a recent login:

{"active":true,"authType":0,"certificateType":0,"cloudType":0,"accessTokens":{"https://graph.microsoft.com":{"expiresOn":"2024-06-29T00:53:50.000Z","accessToken":"<redacted>","tenant":"common","name":"","identityName":"","identityId":"","identityTenantId":""}

milanholemans commented 1 week ago

So, when you log in and run m365 cli doctor, there are scopes displayed, but when you let the token expire and run it again, the scopes are gone?

ToeKneeFan commented 1 week ago

Thank you again. No, the scopes never show in the result of m365 cli doctor, but the requested scopes work properly during the initial access-token lifetime and associated commands work. They also show properly in the permissions webpage in the DeviceCode workflow.

Notably, in v7.4.0 (where the token refreshing works properly), m365 cli doctor likewise does not show any scopes. I think m365 cli doctor is just an "unreliable narrator" in my situation. I wonder if this is a result of using the common tenant with a custom app registration (perhaps a unique situation, hence why it has not been reported).

waldekmastykarz commented 6 days ago

Just to confirm @ToeKneeFan, your custom Entra app, that you're using with CLI, is a multitenant app, correct?

ToeKneeFan commented 5 days ago

@waldekmastykarz Thank you for your help! Yes, it is configured for any tenant or a personal account ("Accounts in any organizational directory (Any Microsoft Entra ID tenant - Multitenant) and personal Microsoft accounts (e.g. Skype, Xbox)").

waldekmastykarz commented 5 days ago

Thank you for confirming, @ToeKneeFan. It'll help us repro and fix the issue

ToeKneeFan commented 5 days ago

This is probably unnecessary, but for sake of completeness, I also reproduced this issue on Windows 11 as well (to verify reproducibility and ensure it is not isolated to just Linux). (Windows 11 Pro 10.0.22631 Build 22631, npm v10.8.1, m365 v7.9.0 and v7.10.0)

waldekmastykarz commented 4 days ago

Something what you said grabbed my attention:

I may be in a somewhat rare situation, since I am using a personal account without a dedicated tenant ("common") and with a custom app registration; I suspect that most people are using the m365 CLI within a corporate tenant, which may affect reproducibility of this bug.

With personal account do you mean personal as in private/not a service account, or a personal account like Microsoft personal account aka. Live account aka. Hotmail?

I'm trying to reproduce your setup. I've just created a new multitenant app with custom permissions and m365 status shows just fine. Also m365 cli doctor shows the connection details as expected. Let's see if we can figure out what's wrong exactly.

ToeKneeFan commented 4 days ago

With personal account do you mean personal as in private/not a service account, or a personal account like Microsoft personal account aka. Live account aka. Hotmail?

@waldekmastykarz It sounds like the latter; it is a Microsoft 365 Personal account, as described on this page. Yes, the email is associated with Outlook.com, which replaced Hotmail.

waldekmastykarz commented 3 days ago

Microsoft 365 Personal is a SKU rather than an account type. I don't think we've ever tested using personal accounts with CLI. There are a lot of restrictions and not all APIs work with personal accounts. I can see if we can fix the login, but can't guarantee that the whole CLI will work as intended.

Out of curiosity, why are you using this setup rather than a work account?

waldekmastykarz commented 3 days ago

I can replicate the issue that you're seeing when I use a personal account to sign it to CLI for M365:

That said, I'm not quite sure if this is a setup that we should support. Could you please help us understand why you're using a personal account to manage your M365 tenant, rather than using a work account?

ToeKneeFan commented 2 days ago

Ah, thank you, I was unsure if it was necessarily an account type, though I imagine it would introduce differences in API use.

In my use case, I am primarily using it as an interface for emails from the command line. It seemed to be the most convenient way for OAuth2-based access to Outlook email.

ToeKneeFan commented 1 day ago

Completely understand if it would not be feasible to continue supporting this use case. If so, it may make sense to formally deprecate it within the documentation.

pnp / cli-microsoft365