invalid_grant after running Suspend-PartnerAzureSubscription

[slavizh]

Steps to reproduce

What steps can reproduce the defect?
Please share the setup, commandline for vstest.console, sample project, target
framework etc.

I am running the below commands to suspend Azure Plan subscription. From Get-PartnerCustomerAzurePlanEntitlement I get the id of the subscription and put it on SubscriptionId property. After the command is executed I get some weird output and I cannot longer run Get-PartnerCustomerAzurePlanEntitlement . I had to re-connect so I can run the command again. After running the subscription is still shown as active. So the command does not work but also breaks authentication. I am using refresh token. I have posted also debug of the command. Sensitive values are removed. Also Enable does not work as well as you can see.

Get-PartnerCustomerAzurePlanEntitlement -CustomerId -SubscriptionId 

<results are returned>

Suspend-PartnerAzureSubscription -CustomerId  -SubscriptionId 
System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1[Microsoft.Azure.Management.Profiles.Subscription.Models.CanceledSubscriptionId]

Get-PartnerCustomerAzurePlanEntitlement -CustomerId -SubscriptionId 
Get-PartnerCustomerAzurePlanEntitlement : Invalid authorization bearer is passed (invalid_grant)
At line:1 char:1
+ Get-PartnerCustomerAzurePlanEntitlement -CustomerId ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : CloseError: (:) [Get-PartnerCustomerAzurePlanEntitlement], PartnerException
    + FullyQualifiedErrorId : Microsoft.Store.PartnerCenter.PowerShell.Commands.GetPartnerCustomerAzurePlanEntitlement

Get-PartnerCustomerAzurePlanEntitlement -CustomerId  -SubscriptionId  -Debug
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) MSAL MSAL.CoreCLR with assembly version '4.5.1.0'.
CorrelationId(9e8584e2-48fc-4e5f-a677-7b4765d995d1)

Confirm
Continue with this operation?
[Y] Yes  [A] Yes to All  [H] Halt Command  [S] Suspend  [?] Help (default is "Y"): a
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) === OnBehalfOfParameters ===
LoginHint provided: False
User provided: True
ForceRefresh: False
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0)
=== Request Data ===
Authority Provided? - True
Scopes - https://api.partnercenter.microsoft.com/user_impersonation
Extra Query Params Keys (space separated) -
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) === Token Acquisition (SilentRequest) started:

 Authority Host: login.microsoftonline.com
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) Looking up access token in the cache.
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) Filtering by tenant id item count before 8 after 2
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) Filtering by home account id item count before 2 after 2
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) Matching entry count -2
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) Matching entry count after filtering by scopes - 1
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) Access token is not expired. Returning the found cache entry.  [Current time (12/12/2019 07:59:20) - Expiration Time (12/12/2019 08:58:42 +00:00) - Extended Expiration Time (12/12/2019 08:58:42 +00:00)]
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) Returning access token found in cache. RefreshOn exists ?     False
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 07:59:20 - 9e8584e2-48fc-4e5f-a677-7b4765d995d1] (UnknownClient: 0.0.0.0) === Token Acquisition finished successfully. An access token  was returned with Expiration Time: 12/12/2019 08:58:42 +00:00 ===
DEBUG: ============================ HTTP REQUEST ============================
HTTP Method:
GET

Absolute Uri:
https://api.partnercenter.microsoft.com/v1/customers<>/subscriptions/<>/azureEntitlements

Headers:
Accept                        : application/json
MS-PartnerCenter-Client       : Partner Center PowerShell
MS-CorrelationId              : a97bda10-2652-437b-8357-e5f1b9ac007e
X-Locale                      : en-US
MS-RequestId                  : a8f021b9-7188-412b-bbc5-3b9dac25b2c2
MS-SdkVersion                 : 1.15.3.0
DEBUG: ============================ HTTP RESPONSE ============================
Status Code:
Unauthorized

Headers:
MS-CorrelationId              : a97bda10-2652-437b-8357-e5f1b9ac007e
MS-RequestId                  : a8f021b9-7188-412b-bbc5-3b9dac25b2c2
X-Locale                      : en-US
Request-Context               : appId=cid-v1:03ce8ca8-8373-4021-8f25-d5dd45c7b12f
Date                          : Thu, 12 Dec 2019 07:59:27 GMT
WWW-Authenticate              : Bearer,Bearer,Bearer,Bearer,Bearer,Bearer,Bearer,Bearer,Bearer

Body:


Confirm
Invalid authorization bearer is passed (invalid_grant)
[Y] Yes  [A] Yes to All  [H] Halt Command  [S] Suspend  [?] Help (default is "Y"): a
Get-PartnerCustomerAzurePlanEntitlement : Invalid authorization bearer is passed (invalid_grant)
At line:1 char:1
+ Get-PartnerCustomerAzurePlanEntitlement -CustomerId  ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : CloseError: (:) [Get-PartnerCustomerAzurePlanEntitlement], PartnerException
    + FullyQualifiedErrorId : Microsoft.Store.PartnerCenter.PowerShell.Commands.GetPartnerCustomerAzurePlanEntitlement

Suspend-PartnerAzureSubscription -CustomerId  -SubscriptionId  -Debug
DEBUG: [RefreshTokenAuthenticator] Calling GetAccountsAysnc

Confirm
Continue with this operation?
[Y] Yes  [A] Yes to All  [H] Halt Command  [S] Suspend  [?] Help (default is "Y"): a
DEBUG: [RefreshTokenAuthenticator] Calling AcquireTokenSilent - Scopes: 'https://management.azure.com//user_impersonation'
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) MSAL MSAL.CoreCLR with assembly version '4.5.1.0'.
CorrelationId(f65b58d4-9f1e-4e12-af99-0739c73ece33)
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) === OnBehalfOfParameters ===
LoginHint provided: False
User provided: True
ForceRefresh: False
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0)
=== Request Data ===
Authority Provided? - True
Scopes - https://management.azure.com//user_impersonation
Extra Query Params Keys (space separated) -
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) === Token Acquisition (SilentRequest) started:

 Authority Host: login.microsoftonline.com
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) Looking up access token in the cache.
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) Filtering by tenant id item count before 8 after 2
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) Filtering by home account id item count before 2 after 2      DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) Matching entry count -2
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) Matching entry count after filtering by scopes - 1
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) Access token is not expired. Returning the found cache entry.  [Current time (12/12/2019 08:08:10) - Expiration Time (12/12/2019 08:58:31 +00:00) - Extended Expiration Time (12/12/2019 08:58:31 +00:00)]
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) Returning access token found in cache. RefreshOn exists ?     False
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:08:10 - f65b58d4-9f1e-4e12-af99-0739c73ece33] (UnknownClient: 0.0.0.0) === Token Acquisition finished successfully. An access token  was returned with Expiration Time: 12/12/2019 08:58:31 +00:00 ===
DEBUG: ============================ HTTP REQUEST ============================
HTTP Method:
POST

Absolute Uri:
https://management.azure.com/subscriptions/<>/providers/Microsoft.Subscription/cancel?api-version=2019-03-01-preview

Headers:
x-ms-client-request-id        : 121dc121-35e2-4a8a-958b-9ea977d4761f
accept-language               : en-US
System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1[Microsoft.Azure.Management.Profiles.Subscription.Models.CanceledSubscriptionId]

Enable-PartnerAzureSubscription -CustomerId  -SubscriptionId  -debug
DEBUG: [RefreshTokenAuthenticator] Calling GetAccountsAysnc

Confirm
Continue with this operation?
[Y] Yes  [A] Yes to All  [H] Halt Command  [S] Suspend  [?] Help (default is "Y"): a
DEBUG: [RefreshTokenAuthenticator] Calling AcquireTokenSilent - Scopes: 'https://management.azure.com//user_impersonation'
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) MSAL MSAL.CoreCLR with assembly version '4.5.1.0'.
CorrelationId(6656bfe1-e0ba-4d02-a987-1ce4c3e5c025)
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) === OnBehalfOfParameters ===
LoginHint provided: False
User provided: True
ForceRefresh: False
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0)
=== Request Data ===
Authority Provided? - True
Scopes - https://management.azure.com//user_impersonation
Extra Query Params Keys (space separated) -
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) === Token Acquisition (SilentRequest) started:

 Authority Host: login.microsoftonline.com
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) Looking up access token in the cache.
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) Filtering by tenant id item count before 8 after 2
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) Filtering by home account id item count before 2 after 2      DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) Matching entry count -2
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) Matching entry count after filtering by scopes - 1
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) Access token is not expired. Returning the found cache entry.  [Current time (12/12/2019 08:12:30) - Expiration Time (12/12/2019 08:58:31 +00:00) - Extended Expiration Time (12/12/2019 08:58:31 +00:00)]
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) Returning access token found in cache. RefreshOn exists ?     False
DEBUG: MSAL Info False (False) MSAL 4.5.1.0 MSAL.CoreCLR N/A [12/12/2019 08:12:30 - 6656bfe1-e0ba-4d02-a987-1ce4c3e5c025] (UnknownClient: 0.0.0.0) === Token Acquisition finished successfully. An access token  was returned with Expiration Time: 12/12/2019 08:58:31 +00:00 ===
DEBUG: ============================ HTTP REQUEST ============================
HTTP Method:
POST

Absolute Uri:
https://management.azure.com/subscriptions/<>/providers/Microsoft.Subscription/enable?api-version=2019-03-01-preview

Headers:
x-ms-client-request-id        : 63f44a34-0eac-44f8-8dae-6555690d6cc3
accept-language               : en-US
DEBUG: ============================ HTTP RESPONSE ============================
Status Code:
NotFound

Headers:
Pragma                        : no-cache
x-ms-failure-cause            : gateway
x-ms-request-id               : 0bdd7f72-4254-472f-94f7-e9a77b828e0d
x-ms-correlation-request-id   : 0bdd7f72-4254-472f-94f7-e9a77b828e0d
x-ms-routing-request-id       : CANADAEAST:20191212T081238Z:0bdd7f72-4254-472f-94f7-e9a77b828e0d
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Thu, 12 Dec 2019 08:12:37 GMT

Body:
{
  "error": {
    "code": "SubscriptionNotFound",
    "message": "The subscription '<>' could not be found."
  }
}
System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1[Microsoft.Azure.Management.Profiles.Subscription.Models.EnabledSubscriptionId]

Expected behavior

Share the expected output

Actual behavior

What is the behavior observed?

Diagnostic logs

Please share test platform diagnostics logs.
The logs may contain test assembly paths, kindly review and mask those before sharing.

Environment

Please share additional details about your environment.
Version

[slavizh]

When I checked a few hours later I saw the the subscription turned into Disabled state. Still there is some problem with the command as it:

• breaks authentication
• output should be something better and it should handle errors
• Change should be visible right away when you use Get-PartnerCustomerAzurePlanEntitlement

I have tried the enable command but that one still gives the same error and after 5 minutes the status of the subscription is still not changed.

[slavizh]

In the activity log of the subscription around the the time of suspending I see the following error. Not sure how much related it is.

   "level": "Error",
    "operationId": "c772c7d2-34d7-42e6-9bfc-b6370345988d",
    "operationName": {
        "value": "Microsoft.Subscription/cancel/action",
        "localizedValue": "Cancel Subscription"
    },
    "resourceGroupName": "",
    "resourceProviderName": {
        "value": "Microsoft.Subscription",
        "localizedValue": "Microsoft.Subscription"
    },
    "resourceType": {
        "value": "",
        "localizedValue": ""
    },
    "resourceId": "/subscriptions/<>/providers/Microsoft.Subscription",
    "status": {
        "value": "Failed",
        "localizedValue": "Failed"
    },
    "subStatus": {
        "value": "499",
        "localizedValue": "499"
    },
    "submissionTimestamp": "2019-12-12T08:09:46.1336217Z",
    "subscriptionId": "<>",
    "properties": {
        "statusCode": "499",
        "serviceRequestId": null,
        "statusMessage": "{\"error\":{\"code\":\"ClientClosedRequest\",\"message\":\"The connection has been closed by the client while the server is still processing its request for 'Microsoft.Subscription'.\"}}"
    },
    "relatedEvents": []
}

[ghost]

@slavizh unfortunately suspending a subscription that is an Azure Plan can take up to ten minutes to reflect the changes through the API and the portal. The following message is displayed when you suspend a subscription through the portal

You have successfully canceled subscription Microsoft Azure Test, but it may take some time for the portal to reflect the change. Please try refreshing the page in 10 minutes.

The status available through the get Azure entitlement command will reflect the modified status after everything has a chance to synchronize. Taking this into consideration there is not anything that can be done through this module to make reflection happen more quickly.

With respect to the authentication error that you are encountering let me look into that. I will keep you posted on what I am able to discover.

[ghost]

@slavizh one quick update all of the required code changes have been made. Due to the holidays we will not release another version of the module this year. After the first of the year a new release will be published that contains a hotfix for these issues.

[ghost]

@slavizh I decided to release the next version early to help unblock a handful of scenarios. Starting with version 3.0.3 this issue has been addressed through this release. Please let us know if you encounter any other issue.