Linked Questions

Popular Questions

I met an issue when doing swap on Azure Portal.

There are 2 slots, production and blue in our App Service. And we have 2 instances. Both slots and instances well before swapping. Swap action is swapping blue to production(not swap with preview action).

After swapped, one of instance seems not worked properly. Website logs like this:

  • 06:07:44, 1 request for SiteWarmup, response as 200 OK
  • 06:07:45 ~ 06:07:59, 2 times heartbeat and response as 200 OK
  • 06:08:00 ~ 06:09:27, no request
  • 06:09:28 ~ 06:09:36, 13 requests for our APIs, 200 response but take long time.(about 1 second in normal but over 20 second got here)
  • 06:09:37 ~ 06:11:41, no request again
  • 06:11:42 ~ 06:23:38, bit less than 2000 times requests, all except 10 heartbeat are response as 500 time out, after 230 seconds for each API.

In application log, there are only 213 times records from 06:07:53 to 06:09:36, nothing in later 14 minutes. 202 of all is Token Acquisition operation for Microsoft.IdentityModel.Clients.ActiveDirectory.TokenCache, but got same Hash, looks strange for me.

    2017-04-19T06:09:34,Information,{my-service-name},d659c0,636281789745216643,0,4252,30,"4/19/2017 6:09:34 AM: 88404b06-f143-4de1-99c1-aa2779516c3b - AcquireTokenHandlerBase: === Token Acquisition started:
        Authority: https://login.windows.net/{my-domain}/
        Resource: https://graph.windows.net
        ClientId: {my-client-id}
        CacheType: Microsoft.IdentityModel.Clients.ActiveDirectory.TokenCache (1 items)
        Authentication Target: Client
        ",00000000-0000-0000-0200-008000000056
    2017-04-19T06:09:34,Information,{my-service-name},d659c0,636281789745216643,0,4252,30,4/19/2017 6:09:34 AM: 88404b06-f143-4de1-99c1-aa2779516c3b - TokenCache: Looking up cache for a token...,00000000-0000-0000-0200-008000000056
    2017-04-19T06:09:34,Information,{my-service-name},d659c0,636281789745216643,0,4252,30,4/19/2017 6:09:34 AM: 88404b06-f143-4de1-99c1-aa2779516c3b - TokenCache: An item matching the requested resource was found in the cache,00000000-0000-0000-0200-008000000056
    2017-04-19T06:09:34,Information,{my-service-name},d659c0,636281789745216643,0,4252,30,4/19/2017 6:09:34 AM: 88404b06-f143-4de1-99c1-aa2779516c3b - TokenCache: 58.305389355 minutes left until token in cache expires,00000000-0000-0000-0200-008000000056
    2017-04-19T06:09:34,Information,{my-service-name},d659c0,636281789745216643,0,4252,30,4/19/2017 6:09:34 AM: 88404b06-f143-4de1-99c1-aa2779516c3b - TokenCache: A matching item (access token or refresh token or both) was found in the cache,00000000-0000-0000-0200-008000000056
    2017-04-19T06:09:34,Information,{my-service-name},d659c0,636281789745216643,0,4252,30,"4/19/2017 6:09:34 AM: 88404b06-f143-4de1-99c1-aa2779516c3b - AcquireTokenHandlerBase: === Token Acquisition finished successfully. An access token was retuned:
        Access Token Hash: {same-hash}
        Refresh Token Hash: [No Refresh Token]
        Expiration Time: 4/19/2017 7:07:52 AM +00:00
        User Hash: null
        ",00000000-0000-0000-0200-008000000056

Meanwhile, another instance works well, over 100 requests per minute and no other than 200 OK. process time is also normal, most is less than 1 second.

And I noticed 2 things in Metrics Per Instance monitoring.

  • this instance has a high CPU usage, 10 times more than another one.
  • this instance has a Http Queue Length equal to 8.0, but nothing other than 0.0 I can found in other time or other instance.

Then swapped production back to blue, both instances and slots worked again.

It is the first time we met this issue, never happened before on same deployment. Is there any possibility to cause this issue, how can I resolve or avoid it?

Thank you for your advice in advance.

Regards

Kong

Related Questions