Azure-sdk-for-js: Acquiring new Azure AD access token for every request instead reusing the access token till it's validity time

[prashanthmadduri]

• Package Name: @azure/storage-blob, @azure/identity
• Package Version: 12.3.0, 1.2.0
• Operating system: Windows 10
• [X] nodejs
  
  
  
  • version: v10.16.3
  
  
• [ ] browser
  
  
  
  • name/version:
  
  
• [ ] typescript
  
  
  
  • version: v1.5.3
  
  
• Is the bug related to documentation in
  
  
  
  • [ ] README.md
  
  
  • [ ] source code documentation
  
  
  • [X] SDK API docs on https://docs.microsoft.com
  
  

Describe the bug
A clear and concise description of what the bug is.
We are using ClientSecretCredential for Azure AD authentication for Azure Blob service. As per our observation based on the logging the Azure Blob Javascript SDK is not reusing the Azure AD access token generated for immediate requests instead it is generating fresh token for every request.

To Reproduce
Steps to reproduce the behavior:

1. Use the below provided sample code and run the program using NodeJS command. Access the program from browser using URL http://localhost:3022/, you can see acquiring the Azure AD access token which is valid for one hour.

const express = require('express')
const app = express()
const { BlobServiceClient } = require('@azure/storage-blob')
const { ClientSecretCredential } = require('@azure/identity')
const logger = require('@azure/logger')
app.get('/', (req, res) => {
  try {
    logger.setLogLevel('verbose')
    const account = '<<teststorageaccount>>'
    const clientSecretCredential = new ClientSecretCredential('<<TenantId>>', '<<ClientId>>', '<<ClientSecret>>')
    const containerName = '<<testcontainer>>'
    const blobName = 'test_blob.txt'
    const blobServiceClient = new BlobServiceClient(
      `https://${account}.blob.core.windows.net`,
      clientSecretCredential
    )
    const containerClient = blobServiceClient.getContainerClient(containerName)
    const blockBlobClient = containerClient.getBlockBlobClient(blobName)
    const downloadBlobResponse = blockBlobClient.download(0)
    downloadBlobResponse.then(function convertStream2Buffer(downloadBlobResponse) {
        const fileContent = streamToBuffer(downloadBlobResponse.readableStreamBody)
        fileContent.then((data) => {
          console.log(`Downloaded Blob Response for '${blobName}' data.length bytes is :::  `, data.length)
          console.log('$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$')
          res.send('SSSUUUUCCCCCEEEEEEEESSSSSSSS!!!!!!!!!!  data.length bytes #####  ' + data.length)
        })
      }
    )    
  } catch (err) {
    console.log('EEEEEEEEEEERRRRRRRRRRRRRRROOOOOOOOOOOOORRRRRRRRRRRRR  : ', err)
  }
})

function streamToBuffer (readableStream) {
  return new Promise((resolve, reject) => {
    const chunks = []
    readableStream.on('data', (data) => {
      chunks.push(data instanceof Buffer ? data : Buffer.from(data))
    })
    readableStream.on('end', () => {
      resolve(Buffer.concat(chunks))
    })
    readableStream.on('error', reject)
  })
}

app.listen(3022, function () {
  console.log('app listening on port 3022!')
})

Logs from the first execution where it shows acquiring access token which is valid for one hour.

D:\AzureBlob> node BlobClient_verify_token_generation.js
app listening on port 3022!
azure:core-http:info ServiceClient: using custom request policies
azure:core-http:info ServiceClient: using custom request policies
azure:core-http:info ServiceClient: using custom request policies
azure:core-http:info ServiceClient: using custom request policies
azure:storage-blob:info RetryPolicy: =====> Try=1 Primary        
azure:storage-blob:info Request: {
  "streamResponseBody": true,
  "url": "https://<<teststorageaccount>>.blob.core.windows.net/<<testcontainer>>/test_blob.txt",
  "method": "GET",
  "headers": {
    "_headersMap": {
      "x-ms-version": "2020-04-08",
      "user-agent": "azsdk-js-storageblob/12.4.0 (NODE-VERSION v10.16.3; Windows_NT 10.0.19041)",
      "x-ms-client-request-id": "002dd0b-36cd-4700-b0d6-c01e0f99dcd"
    }
  },
  "withCredentials": false,
  "timeout": 0,
  "keepAlive": true,
  "requestId": "002dd0b-36cd-4700-b0d6-c01e0f99dcd"
}
azure:identity:info IdentityClient: sending token request to [https://login.microsoftonline.com/<<TenantId>>/oauth2/v2.0/token]
azure:core-http:info Request: {
  "url": "https://login.microsoftonline.com/<<TenantId>>/oauth2/v2.0/token",
  "method": "POST",
  "headers": {
    "_headersMap": {
      "accept": "application/json",
      "content-type": "application/x-www-form-urlencoded",
      "accept-language": "REDACTED",
      "x-ms-client-request-id": "7d873f-f571-4c7c-be1e-17b29b2d81",
      "user-agent": "core-http/1.2.1 Node/v10.16.3 OS/(x64-Windows_NT-10.0.19041)"
    }
  },
  "withCredentials": false,
  "timeout": 0,
  "keepAlive": true,
  "requestId": "7d873f-f571-4c7c-be1e-17b29b2d81"
}
azure:core-http:info Response status code: 200
azure:core-http:info Headers: {
  "_headersMap": {
    "cache-control": "no-store, no-cache",
    "content-length": "1316",
    "content-type": "application/json; charset=utf-8",
    "date": "Mon, 25 Jan 2021 07:56:48 GMT",
    "expires": "-1",
    "p3p": "REDACTED",
    "pragma": "no-cache",
    "set-cookie": "REDACTED",
    "strict-transport-security": "REDACTED",
    "x-content-type-options": "REDACTED",
    "x-ms-ests-server": "REDACTED",
    "x-ms-request-id": "58486a-756e-4af3-bca-9dd52435100"
  }
}
azure:identity:info IdentityClient: [https://login.microsoftonline.com/<<TenantId>>/oauth2/v2.0/token] token acquired, expires on 1611565008171
azure:identity:info ClientSecretCredential => getToken() => SUCCESS. Scopes: https://storage.azure.com/.default.
azure:storage-blob:info Response status code: 200
azure:storage-blob:info Headers: {
  "_headersMap": {
    "accept-ranges": "bytes",
    "access-control-allow-origin": "*",
    "access-control-expose-headers": "x-ms-request-id,x-ms-client-request-id,Server,x-ms-version,x-ms-version-id,x-ms-is-current-version,Content-Type,Last-Modified,ETag,x-ms-creation-time,Content-MD5,x-ms-lease-status,x-ms-lease-state,x-ms-blob-type,x-ms-server-encrypted,Accept-Ranges,Content-Length,Date,Transfer-Encoding",
    "content-length": "11",
    "content-md5": "sQqNsWTgdUEFddft6mb5y4/5Q==",
    "content-type": "application/octet-stream",
    "date": "Mon, 25 Jan 2021 07:56:49 GMT",
    "etag": "\"0x8DG8BD42dwB018D3E5C1\"",
    "last-modified": "Wed, 20 Jan 2021 12:55:39 GMT",
    "server": "Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0",
    "x-ms-blob-type": "BlockBlob",
    "x-ms-client-request-id": "002sddd0b-36cd-4700-b0d6-c01we0f99dcd",
    "x-ms-creation-time": "Wed, 20 Jan 2021 12:55:39 GMT",
    "x-ms-is-current-version": "REDACTED",
    "x-ms-lease-state": "available",
    "x-ms-lease-status": "unlocked",
    "x-ms-request-id": "38f8csd972-001e-006e-6ewef-f2f912s000000",
    "x-ms-server-encrypted": "true",
    "x-ms-version": "2020-04-08",
    "x-ms-version-id": "REDACTED"
  }
}
Downloaded Blob Response for 'test_blob.txt' data.length bytes is :::   11
$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$

1. Refresh the browser and you can again see the logs for acquiring the new Azure AD access token with one hour validity. Below is the logs for the 2nd execution.

azure:core-http:info ServiceClient: using custom request policies
azure:core-http:info ServiceClient: using custom request policies
azure:core-http:info ServiceClient: using custom request policies
azure:core-http:info ServiceClient: using custom request policies
azure:storage-blob:info RetryPolicy: =====> Try=1 Primary
azure:storage-blob:info Request: {
  "streamResponseBody": true,
  "url": "https://<<teststorageaccount>>.blob.core.windows.net/<<testcontainer>>/test_blob.txt",
  "method": "GET",
  "headers": {
    "_headersMap": {
      "x-ms-version": "2020-04-08",
      "user-agent": "azsdk-js-storageblob/12.4.0 (NODE-VERSION v10.16.3; Windows_NT 10.0.19041)",
      "x-ms-client-request-id": "547dwe3314c-ae12-41eeb-9a4a-a036dewc7c0a"
    }
  },
  "withCredentials": false,
  "timeout": 0,
  "keepAlive": true,
  "requestId": "547dwe3314c-ae12-41eeb-9a4a-a036dewc7c0a"
}
azure:identity:info IdentityClient: sending token request to [https://login.microsoftonline.com/<<TenantId>>/oauth2/v2.0/token]
azure:core-http:info Request: {
  "url": "https://login.microsoftonline.com/<<TenantId>>/oauth2/v2.0/token",
  "method": "POST",
  "headers": {
    "_headersMap": {
      "accept": "application/json",
      "content-type": "application/x-www-form-urlencoded",
      "accept-language": "REDACTED",
      "x-ms-client-request-id": "38eefa81-26c7-4fa4-8we7-b486ds929b47",
      "user-agent": "core-http/1.2.1 Node/v10.16.3 OS/(x64-Windows_NT-10.0.19041)"
    }
  },
  "withCredentials": false,
  "timeout": 0,
  "keepAlive": true,
  "requestId": "38eefa81-26c7-4fa4-8we7-b486ds929b47"
}
azure:core-http:info Response status code: 200
azure:core-http:info Headers: {
  "_headersMap": {
    "cache-control": "no-store, no-cache",
    "content-length": "1316",
    "content-type": "application/json; charset=utf-8",
    "date": "Mon, 25 Jan 2021 07:56:54 GMT",
    "expires": "-1",
    "p3p": "REDACTED",
    "pragma": "no-cache",
    "set-cookie": "REDACTED",
    "strict-transport-security": "REDACTED",
    "x-content-type-options": "REDACTED",
    "x-ms-ests-server": "REDACTED",
    "x-ms-request-id": "80bsdwd4-a473-4994-94wew-6sdc28dwew5800"
  }
}
azure:identity:info IdentityClient: [https://login.microsoftonline.com/<<TenantId>>/oauth2/v2.0/token] token acquired, expires on 1611565013531
azure:identity:info ClientSecretCredential => getToken() => SUCCESS. Scopes: https://storage.azure.com/.default.
azure:storage-blob:info Response status code: 200
azure:storage-blob:info Headers: {
  "_headersMap": {
    "accept-ranges": "bytes",
    "access-control-allow-origin": "*",
    "access-control-expose-headers": "x-ms-request-id,x-ms-client-request-id,Server,x-ms-version,x-ms-version-id,x-ms-is-current-version,Content-Type,Last-Modified,ETag,x-ms-creation-time,Content-MD5,x-ms-lease-status,x-ms-lease-state,x-ms-blob-type,x-ms-server-encrypted,Accept-Ranges,Content-Length,Date,Transfer-Encoding",
    "content-length": "11",
    "content-md5": "sQqNsWTgdUEFddft6mb5y4/5Q==",
    "content-type": "application/octet-stream",
    "date": "Mon, 25 Jan 2021 07:56:54 GMT",
    "etag": "\"0x8DG8BD42dwB018D3E5C1\"",
    "last-modified": "Wed, 20 Jan 2021 12:55:39 GMT",
    "server": "Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0",
    "x-ms-blob-type": "BlockBlob",
    "x-ms-client-request-id": "547dwe3314c-ae12-41eeb-9a4a-a036dewc7c0a",
    "x-ms-creation-time": "Wed, 20 Jan 2021 12:55:39 GMT",
    "x-ms-is-current-version": "REDACTED",
    "x-ms-lease-state": "available",
    "x-ms-lease-status": "unlocked",
    "x-ms-request-id": "38sdwed-001e-00sdw6e-6def-f2sdwe2000000",
    "x-ms-server-encrypted": "true",
    "x-ms-version": "2020-04-08",
    "x-ms-version-id": "REDACTED"
  }
}
Downloaded Blob Response for 'test_blob.txt' data.length bytes is :::   11
$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$

Expected behavior
A clear and concise description of what you expected to happen.

The subsequent API calls through Azure AD authentication should use the Azure AD access token till it's validity ends and the SDK should re-generate the access token on it's expire. In this case the access token generation should be for every one hour considering we are running it as web application.

Screenshots
If applicable, add screenshots to help explain your problem.

Additional context
Add any other context about the problem here.

We have app registration created and Storage Blob Data Contributor role assigned. The access to Azure Blob is working without any issue. Only concern is on new token generation for every request.

If the SDK is designed to work in that way is there any limit on the maximum number of tokens generated per account?

[sadasant]

@prashanthmadduri thank you! I'll be investigating this with more detail this week.

[prashanthmadduri]

@sadasant any inputs here will help us. Thank you.

[sadasant]

@prashanthmadduri

Hello! The reason why this is happening is because a new instance of the credential and the client are created per request. We re-use the tokens as long as the same instances are re-used (because inside of the instances is where we store the valid tokens).

To avoid seeing this many extra requests, consider moving the declaration of both the ClientSecretCredential and the BlobServiceClient outside of the route app.get('/' /*...*/.

An example, in case my wording wasn't helpful:

/* Into here: */
const account = '<<teststorageaccount>>'
const clientSecretCredential = new ClientSecretCredential('<<TenantId>>', '<<ClientId>>', '<<ClientSecret>>')
const containerName = '<<testcontainer>>'
const blobName = 'test_blob.txt'
const blobServiceClient = new BlobServiceClient(
  `https://${account}.blob.core.windows.net`,
  clientSecretCredential
);

app.get('/', (req, res) => {
  try {
    logger.setLogLevel('verbose')
    /* out of here:
    const account = '<<teststorageaccount>>'
    const clientSecretCredential = new ClientSecretCredential('<<TenantId>>', '<<ClientId>>', '<<ClientSecret>>')
    const containerName = '<<testcontainer>>'
    const blobName = 'test_blob.txt'
    const blobServiceClient = new BlobServiceClient(
      `https://${account}.blob.core.windows.net`,
      clientSecretCredential
    )
    */

Would that work for you?

[prashanthmadduri]

@sadasant thank you for your inputs. I have tried by moving the instance creation outside app.get as suggested. In some subsequent executions still I can see token regeneration before the present token expiry.

First request generated token:

The request details:
"x-ms-client-request-id": "eb5574d9-7945-4148-b98a-828d9cf36cdb"
"x-ms-request-id": "3df5f824-e01e-003b-0422-f9e999000000"

The token is valid till 2021-02-02T06:17:16.271Z(1612246636271) time.

In subsequent request with in the above token expiry:

The request details:
"x-ms-client-request-id": "aed4c805-d599-4389-bc8c-01990f7650b9"
"x-ms-request-id": "3df6460b-e01e-003b-2a22-f9e999000000"

New token generated which is valid till 2021-02-02T06:17:52.940Z(1612246672940) time.

Based on this, SDK is regenerating new token within the token expiry. Also, all subsequent requests are not generating new tokens all the time. It is random some subsequent requests not generating new token.

Below is the one subsequent request which seems used the existing token:

The request details:
"x-ms-client-request-id": "ec4b1a46-221d-4740-b940-e2feec68b7eb"
"x-ms-request-id": "3df61eb0-e01e-003b-4222-f9e999000000"

Note: The above observation is with all requests executed within one hour.

[sadasant]

@prashanthmadduri Thank you for your detailed answer!

Can you repeat this experiment but also provide the time when the requests were made? I believe we refresh the tokens before they expire, but not by much. The idea is to prevent the clients from losing access by updating the tokens while they're still valid - however, it should be close to the expiration date, this is what I want to confirm.

[prashanthmadduri]

@sadasant we have run the experiment again and can see the new token regeneration within the expiry time of the active token. Please find the response logs captured from the execution for your investigation.

1. Starting the express sever.
2. After server is up sent 1st Request. => New token acquired
3. After couple of minutes again sent 2nd Request.
4. After couple of minutes again sent 3rd Request.
5. Waited for approximately 10minutes and sent request. => New token acquired
6. After couple of minutes again sent 2nd Request.
7. After couple of minutes again sent 3rd Request.
8. Waited for approximately 20minutes and sent request. => New token acquired
9. After couple of minutes again sent 2nd Request.

BlobClient_download_verify_token_generation_04Feb2021.txt

[sadasant]

@prashanthmadduri so far I haven't been able to reproduce this. I will continue testing, but would you be able to provide a minimum working scenario? what's the most minimal code you have that can reproduce this?

[sadasant]

I have yet to run long term tests. I have been trying with tokens with smaller expiration dates and I haven't seen the issue, but I could be doing something wrong. Tomorrow I will have a more concrete response.

[prashanthmadduri]

Sharing code using for this from our side just avoid any mismatch in verification:

const express = require('express')
const app = express()
const { BlobServiceClient } = require('@azure/storage-blob')
const { ClientSecretCredential } = require('@azure/identity')
const logger = require('@azure/logger')

const account = '<<Stroage Account>>'
const clientSecretCredential = new ClientSecretCredential('<<Tenant Id>>', '<<Client Id>>', '<<Client Secret>>')
const containerName = '<<Conatiner>>'
const blobName = 'testBlob.txt'
const blobServiceClient = new BlobServiceClient(
   `https://${account}.blob.core.windows.net`,
   clientSecretCredential
)

app.get('/', (req, res) => {
  try {
    logger.setLogLevel('verbose')
    const containerClient = blobServiceClient.getContainerClient(containerName)
    const blockBlobClient = containerClient.getBlockBlobClient(blobName)
    const downloadBlobResponse = blockBlobClient.download(0)
    downloadBlobResponse.then(function convertStream2Buffer (downloadBlobResponse) {
      const fileContent = streamToBuffer(downloadBlobResponse.readableStreamBody)
      fileContent.then((data) => {
        console.log(`Downloaded Blob Response for '${blobName}' data.length bytes is :::  `, data.length)
        console.log('$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$')
        res.send('SSSUUUUCCCCCEEEEEEEESSSSSSSS!!!!!!!!!!  data.length bytes #####  ' + data.length)
      })
    }
    )
  } catch (err) {
    console.log('EEEEEEEEEEERRRRRRRRRRRRRRROOOOOOOOOOOOORRRRRRRRRRRRR  : ', err)
  }
})

function streamToBuffer (readableStream) {
  return new Promise((resolve, reject) => {
    const chunks = []
    readableStream.on('data', (data) => {
      chunks.push(data instanceof Buffer ? data : Buffer.from(data))
    })
    readableStream.on('end', () => {
      resolve(Buffer.concat(chunks))
    })
    readableStream.on('error', reject)
  })
}

app.listen(3022, function () {
  console.log('app listening on port 3022!')
})

Running this as node application and accessing this from http://localhost:3022/ URL again and again with above https://github.com/Azure/azure-sdk-for-js/issues/13369#issuecomment-773393540 shared scenario.

[sadasant]

@prashanthmadduri Thank you so much for your feedback! Good news! I just happen to have found both the bug and the solution. I just need to add some tests (and have breakfast and such), then we can point you to an alpha release from which you will be able to try the fix! How does that sound?

[sadasant]

@prashanthmadduri thank you again for your effort helping me figure this out! I have a draft PR that will undergo review. As soon as we release something (alpha release will land first, so I will use that), I will let you know 🌞

[prashanthmadduri]

Hi @sadasant Thank you for working on fix for this. We have below questions for the same:

1. Is there any limit on the maximum number of tokens generated?
   
   
   
   • Answer to this question will help to work with Azure AD mean time the fix is available.
   
   
2. When can we expect this fix available for public release?
   
   
   
   • Answer to this question will help us to plan for @azure/storage-blob node module upgrade.
   
   

[sadasant]

@prashanthmadduri

Is there any limit on the maximum number of tokens generated?

Not that I'm aware of.

When can we expect this fix available for public release?

We will release this fix on March.

Please let me know if I can help with anything else!

[sadasant]

@prashanthmadduri hello again! I just wanted to let you know that we're still working on merging the fix. Would you be interested in trying an alpha release we'll publish on NPM with the feature that should resolve your issue? Please let me know and I will link you to it as soon as it is available.

[prashanthmadduri]

@sadasant thank you for update. We will try with final public release with this fix.

[sadasant]

@prashanthmadduri We merged the PR that fixes the issue you saw. We will release this change this week. I will come back with more information by the end of the week.

[sadasant]

@prashanthmadduri We went back and forward and we're working on a different fix: https://github.com/Azure/azure-sdk-for-js/pull/14223

We will release this as soon as possible. Ideally this week.

[sadasant]

@prashanthmadduri it has been a while, but we've finally released core-http version with the fix: https://www.npmjs.com/package/@azure/core-http/v/1.2.4 If you have time to try it, please let us know if you find issues with it, or any other issue you might encounter with any of our SDKs. Thank you for using these libraries!