Merge pull request #5244 from AzureAD/log-x-ms-request-id

Add x-ms-request-id to perf telemetry logging
AzureAD · Sep 29, 2022 · b354804 · b354804
2 parents 1e544dc + 574867a
commit b354804
Show file tree

Hide file tree

Showing 18 changed files with 240 additions and 17 deletions.
diff --git a/change/@azure-msal-browser-a62c8acd-1177-4e1c-8f54-58a5d94140b0.json b/change/@azure-msal-browser-a62c8acd-1177-4e1c-8f54-58a5d94140b0.json
@@ -0,0 +1,7 @@
+{
+  "type": "minor",
+  "comment": "Add x-ms-request-id to perf telemetry logging #5244",
+  "packageName": "@azure/msal-browser",
+  "email": "joarroyo@microsoft.com",
+  "dependentChangeType": "patch"
+}
diff --git a/change/@azure-msal-common-08a34c2d-85fa-4abb-8c29-6291df630f13.json b/change/@azure-msal-common-08a34c2d-85fa-4abb-8c29-6291df630f13.json
@@ -0,0 +1,7 @@
+{
+  "type": "minor",
+  "comment": "Add x-ms-request-id to perf telemetry logging #5244",
+  "packageName": "@azure/msal-common",
+  "email": "joarroyo@microsoft.com",
+  "dependentChangeType": "patch"
+}
diff --git a/lib/msal-browser/src/app/ClientApplication.ts b/lib/msal-browser/src/app/ClientApplication.ts
@@ -353,6 +353,7 @@ export abstract class ClientApplication {
                     isNativeBroker: true,
                     accessTokenSize: response.accessToken.length,
                     idTokenSize: response.idToken.length,
+                    requestId: response.requestId
                 });
                 atPopupMeasurement.flushMeasurement();
                 return response;
@@ -390,6 +391,7 @@ export abstract class ClientApplication {
                 success: true,
                 accessTokenSize: result.accessToken.length,
                 idTokenSize: result.idToken.length,
+                requestId: result.requestId
             });
 
             atPopupMeasurement.flushMeasurement();
@@ -468,7 +470,8 @@ export abstract class ClientApplication {
                 success: true,
                 isNativeBroker: response.fromNativeBroker,
                 accessTokenSize: response.accessToken.length,
-                idTokenSize: response.idToken.length
+                idTokenSize: response.idToken.length,
+                requestId: response.requestId
             });
             ssoSilentMeasurement.flushMeasurement();
             return response;
@@ -518,7 +521,8 @@ export abstract class ClientApplication {
                                 success: true,
                                 accessTokenSize: result.accessToken.length,
                                 idTokenSize: result.idToken.length,
-                                isNativeBroker: result.fromNativeBroker
+                                isNativeBroker: result.fromNativeBroker,
+                                requestId: result.requestId
                             });
                             atbcMeasurement.flushMeasurement();
                             return result;

diff --git a/lib/msal-browser/src/app/PublicClientApplication.ts b/lib/msal-browser/src/app/PublicClientApplication.ts
@@ -136,6 +136,7 @@ export class PublicClientApplication extends ClientApplication implements IPubli
                         idTokenSize: result.idToken.length,
                         isNativeBroker: result.fromNativeBroker,
                         cacheLookupPolicy: request.cacheLookupPolicy,
+                        requestId: result.requestId
                     });
                     atsMeasurement.flushMeasurement();
                     return result;
@@ -241,7 +242,8 @@ export class PublicClientApplication extends ClientApplication implements IPubli
                 fromCache: response.fromCache,
                 accessTokenSize: response.accessToken.length,
                 idTokenSize: response.idToken.length,
-                isNativeBroker: response.fromNativeBroker
+                isNativeBroker: response.fromNativeBroker,
+                requestId: response.requestId
             });
             return response;
         }).catch((tokenRenewalError: AuthError) => {

diff --git a/lib/msal-browser/src/interaction_client/NativeInteractionClient.ts b/lib/msal-browser/src/interaction_client/NativeInteractionClient.ts
@@ -79,7 +79,8 @@ export class NativeInteractionClient extends BaseInteractionClient {
             .then((result: AuthenticationResult) => {
                 nativeATMeasurement.endMeasurement({
                     success: true,
-                    isNativeBroker: true
+                    isNativeBroker: true,
+                    requestId: result.requestId
                 });
                 return result;
             })

diff --git a/lib/msal-browser/src/interaction_client/SilentIframeClient.ts b/lib/msal-browser/src/interaction_client/SilentIframeClient.ts
@@ -64,7 +64,8 @@ export class SilentIframeClient extends StandardInteractionClient {
             return await this.silentTokenHelper(authClient, silentRequest).then((result: AuthenticationResult) => {
                 acquireTokenMeasurement.endMeasurement({
                     success: true,
-                    fromCache: false
+                    fromCache: false,
+                    requestId: result.requestId
                 });
                 return result;
             });

diff --git a/lib/msal-browser/src/interaction_client/SilentRefreshClient.ts b/lib/msal-browser/src/interaction_client/SilentRefreshClient.ts
@@ -28,7 +28,8 @@ export class SilentRefreshClient extends StandardInteractionClient {
             .then((result: AuthenticationResult) => {
                 acquireTokenMeasurement.endMeasurement({
                     success: true,
-                    fromCache: result.fromCache
+                    fromCache: result.fromCache,
+                    requestId: result.requestId
                 });
 
                 return result;

diff --git a/lib/msal-browser/test/app/PublicClientApplication.spec.ts b/lib/msal-browser/test/app/PublicClientApplication.spec.ts
@@ -2637,6 +2637,7 @@ describe("PublicClientApplication.ts Class Unit Tests", () => {
                 expect(events[0].accessTokenSize).toBe(3);
                 expect(events[0].idTokenSize).toBe(4);
                 expect(events[0].isNativeBroker).toBe(true);
+                expect(events[0].requestId).toBe(undefined);
 
                 pca.removePerformanceCallback(callbackId);
                 done();

diff --git a/lib/msal-common/src/client/AuthorizationCodeClient.ts b/lib/msal-common/src/client/AuthorizationCodeClient.ts
@@ -8,7 +8,7 @@ import { CommonAuthorizationUrlRequest } from "../request/CommonAuthorizationUrl
 import { CommonAuthorizationCodeRequest } from "../request/CommonAuthorizationCodeRequest";
 import { Authority } from "../authority/Authority";
 import { RequestParameterBuilder } from "../request/RequestParameterBuilder";
-import { GrantType, AuthenticationScheme, PromptValue, Separators, AADServerParamKeys } from "../utils/Constants";
+import { GrantType, AuthenticationScheme, PromptValue, Separators, AADServerParamKeys, HeaderNames } from "../utils/Constants";
 import { ClientConfiguration } from "../config/ClientConfiguration";
 import { ServerAuthorizationTokenResponse } from "../response/ServerAuthorizationTokenResponse";
 import { NetworkResponse } from "../network/NetworkManager";
@@ -70,6 +70,9 @@ export class AuthorizationCodeClient extends BaseClient {
         const reqTimestamp = TimeUtils.nowSeconds();
         const response = await this.executeTokenRequest(this.authority, request);
 
+        // Retrieve requestId from response headers
+        const requestId = response.headers?.[HeaderNames.X_MS_REQUEST_ID];
+
         const responseHandler = new ResponseHandler(
             this.config.authOptions.clientId,
             this.cacheManager,
@@ -81,7 +84,17 @@ export class AuthorizationCodeClient extends BaseClient {
 
         // Validate response. This function throws a server error if an error is returned by the server.
         responseHandler.validateTokenResponse(response.body);
-        return await responseHandler.handleServerTokenResponse(response.body, this.authority, reqTimestamp, request, authCodePayload);
+        return await responseHandler.handleServerTokenResponse(
+            response.body, 
+            this.authority, 
+            reqTimestamp, 
+            request, 
+            authCodePayload,
+            undefined,
+            undefined,
+            undefined,
+            requestId
+        );
     }
 
     /**

diff --git a/lib/msal-common/src/client/RefreshTokenClient.ts b/lib/msal-common/src/client/RefreshTokenClient.ts
@@ -9,7 +9,7 @@ import { CommonRefreshTokenRequest } from "../request/CommonRefreshTokenRequest"
 import { Authority } from "../authority/Authority";
 import { ServerAuthorizationTokenResponse } from "../response/ServerAuthorizationTokenResponse";
 import { RequestParameterBuilder } from "../request/RequestParameterBuilder";
-import { GrantType, AuthenticationScheme, Errors } from "../utils/Constants";
+import { GrantType, AuthenticationScheme, Errors, HeaderNames } from "../utils/Constants";
 import { ResponseHandler } from "../response/ResponseHandler";
 import { AuthenticationResult } from "../response/AuthenticationResult";
 import { PopTokenGenerator } from "../crypto/PopTokenGenerator";
@@ -40,6 +40,9 @@ export class RefreshTokenClient extends BaseClient {
         const reqTimestamp = TimeUtils.nowSeconds();
         const response = await this.executeTokenRequest(request, this.authority);
 
+        // Retrieve requestId from response headers
+        const requestId = response.headers?.[HeaderNames.X_MS_REQUEST_ID];
+
         const responseHandler = new ResponseHandler(
             this.config.authOptions.clientId,
             this.cacheManager,
@@ -58,7 +61,8 @@ export class RefreshTokenClient extends BaseClient {
             undefined,
             undefined,
             true,
-            request.forceCache
+            request.forceCache,
+            requestId
         );
     }
 

diff --git a/lib/msal-common/src/response/AuthenticationResult.ts b/lib/msal-common/src/response/AuthenticationResult.ts
@@ -19,6 +19,7 @@ import { AccountInfo } from "../account/AccountInfo";
  * - extExpiresOn           - Javascript Date object representing extended relative expiration of access token in case of server outage
  * - state                  - Value passed in by user in request
  * - familyId               - Family ID identifier, usually only used for refresh tokens
+ * - requestId              - Request ID returned as part of the response
  */
 export type AuthenticationResult = {
     authority: string;
@@ -33,6 +34,7 @@ export type AuthenticationResult = {
     expiresOn: Date | null;
     tokenType: string;
     correlationId: string;
+    requestId?: string;
     extExpiresOn?: Date;
     state?: string;
     familyId?: string;

diff --git a/lib/msal-common/src/response/ResponseHandler.ts b/lib/msal-common/src/response/ResponseHandler.ts
@@ -113,7 +113,8 @@ export class ResponseHandler {
         authCodePayload?: AuthorizationCodePayload,
         userAssertionHash?: string,
         handlingRefreshTokenResponse?: boolean,
-        forceCacheRefreshTokenResponse?: boolean): Promise<AuthenticationResult> {
+        forceCacheRefreshTokenResponse?: boolean,
+        serverRequestId?: string): Promise<AuthenticationResult> {
 
         // create an idToken object (not entity)
         let idTokenObj: AuthToken | undefined;
@@ -169,7 +170,7 @@ export class ResponseHandler {
                 const account = this.cacheStorage.getAccount(key);
                 if (!account) {
                     this.logger.warning("Account used to refresh tokens not in persistence, refreshed tokens will not be stored in the cache");
-                    return ResponseHandler.generateAuthenticationResult(this.cryptoObj, authority, cacheRecord, false, request, idTokenObj, requestStateObj, undefined);
+                    return ResponseHandler.generateAuthenticationResult(this.cryptoObj, authority, cacheRecord, false, request, idTokenObj, requestStateObj, undefined, serverRequestId);
                 }
             }
             await this.cacheStorage.saveCacheRecord(cacheRecord);
@@ -179,7 +180,7 @@ export class ResponseHandler {
                 await this.persistencePlugin.afterCacheAccess(cacheContext);
             }
         }
-        return ResponseHandler.generateAuthenticationResult(this.cryptoObj, authority, cacheRecord, false, request, idTokenObj, requestStateObj, serverTokenResponse.spa_code);
+        return ResponseHandler.generateAuthenticationResult(this.cryptoObj, authority, cacheRecord, false, request, idTokenObj, requestStateObj, serverTokenResponse.spa_code, serverRequestId);
     }
 
     /**
@@ -320,6 +321,7 @@ export class ResponseHandler {
         idTokenObj?: AuthToken,
         requestState?: RequestStateObject,
         code?: string,
+        requestId?: string
     ): Promise<AuthenticationResult> {
         let accessToken: string = Constants.EMPTY_STRING;
         let responseScopes: Array<string> = [];
@@ -363,6 +365,7 @@ export class ResponseHandler {
             fromCache: fromTokenCache,
             expiresOn: expiresOn,
             correlationId: request.correlationId,
+            requestId: requestId || Constants.EMPTY_STRING,
             extExpiresOn: extExpiresOn,
             familyId: familyId,
             tokenType: cacheRecord.accessToken?.tokenType || Constants.EMPTY_STRING,

diff --git a/lib/msal-common/src/telemetry/performance/PerformanceEvent.ts b/lib/msal-common/src/telemetry/performance/PerformanceEvent.ts
@@ -298,5 +298,12 @@ export type PerformanceEvent = {
      *
      * @type {?(number | undefined)}
      */
-    cacheLookupPolicy?: number | undefined
+    cacheLookupPolicy?: number | undefined,
+
+    /**
+     * Request ID returned from the response
+     * 
+     * @type {?string}
+     */
+    requestId?: string
 };
diff --git a/lib/msal-common/src/utils/Constants.ts b/lib/msal-common/src/utils/Constants.ts
@@ -72,7 +72,8 @@ export enum HeaderNames {
     RETRY_AFTER = "Retry-After",
     CCS_HEADER = "X-AnchorMailbox",
     WWWAuthenticate = "WWW-Authenticate",
-    AuthenticationInfo = "Authentication-Info"
+    AuthenticationInfo = "Authentication-Info",
+    X_MS_REQUEST_ID = "x-ms-request-id"
 }
 
 /**

diff --git a/lib/msal-common/test/client/AuthorizationCodeClient.spec.ts b/lib/msal-common/test/client/AuthorizationCodeClient.spec.ts
@@ -13,7 +13,9 @@ import {
     POP_AUTHENTICATION_RESULT,
     TEST_ACCOUNT_INFO,
     CORS_SIMPLE_REQUEST_HEADERS,
-    TEST_SSH_VALUES
+    TEST_SSH_VALUES,
+    AUTHENTICATION_RESULT_WITH_HEADERS,
+    CORS_RESPONSE_HEADERS
 } from "../test_kit/StringConstants";
 import { ClientConfiguration } from "../../src/config/ClientConfiguration";
 import { BaseClient } from "../../src/client/BaseClient";
@@ -1894,6 +1896,98 @@ describe("AuthorizationCodeClient unit tests", () => {
             expect(createTokenRequestBodySpy.calledWith(authCodeRequest)).toBeTruthy();
             expect(accessTokenCacheItem && accessTokenCacheItem.refreshOn && accessTokenCacheItem.refreshOn === accessTokenCacheItem.cachedAt + authResult.body.refresh_in);
         });
+
+        it('includes the requestId in the result when received in server response', async () => {
+            sinon.stub(Authority.prototype, <any>"getEndpointMetadataFromNetwork").resolves(DEFAULT_OPENID_CONFIG_RESPONSE.body);
+            sinon.stub(AuthorizationCodeClient.prototype, <any>"executePostToTokenEndpoint").resolves(AUTHENTICATION_RESULT_WITH_HEADERS);
+
+            const config: ClientConfiguration = await ClientTestUtils.createTestClientConfiguration();
+            if (!config.cryptoInterface) {
+                throw TestError.createTestSetupError("configuration cryptoInterface not initialized correctly.");
+            }
+
+            // Set up stubs
+            const idTokenClaims = {
+                "ver": "2.0",
+                "iss": `${TEST_URIS.DEFAULT_INSTANCE}9188040d-6c67-4c5b-b112-36a304b66dad/v2.0`,
+                "sub": "AAAAAAAAAAAAAAAAAAAAAIkzqFVrSaSaFHy782bbtaQ",
+                "exp": 1536361411,
+                "name": "Abe Lincoln",
+                "preferred_username": "AbeLi@microsoft.com",
+                "oid": "00000000-0000-0000-66f3-3332eca7ea81",
+                "tid": "3338040d-6c67-4c5b-b112-36a304b66dad",
+                "nonce": "123523"
+            };
+            sinon.stub(AuthToken, "extractTokenClaims").returns(idTokenClaims);
+            const client = new AuthorizationCodeClient(config);
+            const authCodeRequest: CommonAuthorizationCodeRequest = {
+                authority: Constants.DEFAULT_AUTHORITY,
+                scopes: [...TEST_CONFIG.DEFAULT_GRAPH_SCOPE, ...TEST_CONFIG.DEFAULT_SCOPES],
+                redirectUri: TEST_URIS.TEST_REDIRECT_URI_LOCALHOST,
+                code: TEST_TOKENS.AUTHORIZATION_CODE,
+                codeVerifier: TEST_CONFIG.TEST_VERIFIER,
+                claims: TEST_CONFIG.CLAIMS,
+                correlationId: RANDOM_TEST_GUID,
+                authenticationScheme: AuthenticationScheme.BEARER
+            };
+
+            const authenticationResult = await client.acquireToken(authCodeRequest, {
+                code: authCodeRequest.code,
+                nonce: idTokenClaims.nonce
+            });
+            if (!authenticationResult.expiresOn) {
+                throw TestError.createTestSetupError("mockedAccountInfo does not have a value");
+            }
+
+            expect(authenticationResult.requestId).toBeTruthy;
+            expect(authenticationResult.requestId).toEqual(CORS_RESPONSE_HEADERS.xMsRequestId);
+        });
+
+        it('does not include the requestId in the result when none in server response', async () => {
+            sinon.stub(Authority.prototype, <any>"getEndpointMetadataFromNetwork").resolves(DEFAULT_OPENID_CONFIG_RESPONSE.body);
+            sinon.stub(AuthorizationCodeClient.prototype, <any>"executePostToTokenEndpoint").resolves(AUTHENTICATION_RESULT);
+
+            const config: ClientConfiguration = await ClientTestUtils.createTestClientConfiguration();
+            if (!config.cryptoInterface) {
+                throw TestError.createTestSetupError("configuration cryptoInterface not initialized correctly.");
+            }
+
+            // Set up stubs
+            const idTokenClaims = {
+                "ver": "2.0",
+                "iss": `${TEST_URIS.DEFAULT_INSTANCE}9188040d-6c67-4c5b-b112-36a304b66dad/v2.0`,
+                "sub": "AAAAAAAAAAAAAAAAAAAAAIkzqFVrSaSaFHy782bbtaQ",
+                "exp": 1536361411,
+                "name": "Abe Lincoln",
+                "preferred_username": "AbeLi@microsoft.com",
+                "oid": "00000000-0000-0000-66f3-3332eca7ea81",
+                "tid": "3338040d-6c67-4c5b-b112-36a304b66dad",
+                "nonce": "123523"
+            };
+            sinon.stub(AuthToken, "extractTokenClaims").returns(idTokenClaims);
+            const client = new AuthorizationCodeClient(config);
+            const authCodeRequest: CommonAuthorizationCodeRequest = {
+                authority: Constants.DEFAULT_AUTHORITY,
+                scopes: [...TEST_CONFIG.DEFAULT_GRAPH_SCOPE, ...TEST_CONFIG.DEFAULT_SCOPES],
+                redirectUri: TEST_URIS.TEST_REDIRECT_URI_LOCALHOST,
+                code: TEST_TOKENS.AUTHORIZATION_CODE,
+                codeVerifier: TEST_CONFIG.TEST_VERIFIER,
+                claims: TEST_CONFIG.CLAIMS,
+                correlationId: RANDOM_TEST_GUID,
+                authenticationScheme: AuthenticationScheme.BEARER
+            };
+
+            const authenticationResult = await client.acquireToken(authCodeRequest, {
+                code: authCodeRequest.code,
+                nonce: idTokenClaims.nonce
+            });
+            if (!authenticationResult.expiresOn) {
+                throw TestError.createTestSetupError("mockedAccountInfo does not have a value");
+            }
+
+            expect(authenticationResult.requestId).toBeFalsy;
+            expect(authenticationResult.requestId).toEqual("");
+        });
     });
 
     describe("getLogoutUri()", () => {