More ATS instrumentation

lib/msal-browser/src/interaction_client/SilentCacheClient.ts

@@ -30,6 +30,10 @@ export class SilentCacheClient extends StandardInteractionClient {
     async acquireToken(
         silentRequest: CommonSilentFlowRequest
     ): Promise<AuthenticationResult> {
+        this.performanceClient.addQueueMeasurement(
+            PerformanceEvents.SilentCacheClientAcquireToken,
+            silentRequest.correlationId
+        );
         // Telemetry manager only used to increment cacheHits here
         const serverTelemetryManager = this.initializeServerTelemetryManager(
             ApiId.acquireTokenSilent_silentFlow
@@ -43,9 +47,13 @@ export class SilentCacheClient extends StandardInteractionClient {
         this.logger.verbose("Silent auth client created");
 
         try {
-            const response = await silentAuthClient.acquireCachedToken(
-                silentRequest
-            );
+            const response = await invokeAsync(
+                silentAuthClient.acquireCachedToken.bind(silentAuthClient),
+                PerformanceEvents.SilentFlowClientAcquireCachedToken,
+                this.logger,
+                this.performanceClient,
+                silentRequest.correlationId
+            )(silentRequest);
             const authResponse = response[0] as AuthenticationResult;
 
             this.performanceClient.addFields(

lib/msal-common/src/client/AuthorizationCodeClient.ts

@@ -297,11 +297,18 @@ export class AuthorizationCodeClient extends BaseClient {
 
         return invokeAsync(
             this.executePostToTokenEndpoint.bind(this),
-            PerformanceEvents.BaseClientExecutePostToTokenEndpoint,
+            PerformanceEvents.AuthorizationCodeClientExecutePostToTokenEndpoint,
             this.logger,
             this.performanceClient,
             request.correlationId
-        )(endpoint, requestBody, headers, thumbprint, request.correlationId);
+        )(
+            endpoint,
+            requestBody,
+            headers,
+            thumbprint,
+            request.correlationId,
+            PerformanceEvents.AuthorizationCodeClientExecutePostToTokenEndpoint
+        );
     }
 
     /**

lib/msal-common/src/client/BaseClient.ts

@@ -28,7 +28,6 @@ import { buildClientInfoFromHomeAccountId } from "../account/ClientInfo";
 import { IPerformanceClient } from "../telemetry/performance/IPerformanceClient";
 import { RequestParameterBuilder } from "../request/RequestParameterBuilder";
 import { BaseAuthRequest } from "../request/BaseAuthRequest";
-import { PerformanceEvents } from "../telemetry/performance/PerformanceEvent";
 
 /**
  * Base application class which will construct requests to send to and handle responses from the Microsoft STS using the authorization code flow.
@@ -144,12 +143,10 @@ export abstract class BaseClient {
         queryString: string,
         headers: Record<string, string>,
         thumbprint: RequestThumbprint,
-        correlationId: string
+        correlationId: string,
+        queuedEvent: string
     ): Promise<NetworkResponse<ServerAuthorizationTokenResponse>> {
-        this.performanceClient?.addQueueMeasurement(
-            PerformanceEvents.BaseClientExecutePostToTokenEndpoint,
-            correlationId
-        );
+        this.performanceClient?.addQueueMeasurement(queuedEvent, correlationId);
         const response =
             await this.networkManager.sendPostRequest<ServerAuthorizationTokenResponse>(
                 thumbprint,

lib/msal-common/src/client/RefreshTokenClient.ts

@@ -46,7 +46,7 @@ import {
 } from "../error/InteractionRequiredAuthError";
 import { PerformanceEvents } from "../telemetry/performance/PerformanceEvent";
 import { IPerformanceClient } from "../telemetry/performance/IPerformanceClient";
-import { invokeAsync } from "../utils/FunctionWrappers";
+import { invoke, invokeAsync } from "../utils/FunctionWrappers";
 /**
  * OAuth2.0 refresh token client
  * @internal
@@ -196,10 +196,13 @@ export class RefreshTokenClient extends BaseClient {
         );
 
         // fetches family RT or application RT based on FOCI value
-        const refreshToken = this.cacheManager.getRefreshToken(
-            request.account,
-            foci
-        );
+        const refreshToken = invoke(
+            this.cacheManager.getRefreshToken.bind(this.cacheManager),
+            PerformanceEvents.CacheManagerGetRefreshToken,
+            this.logger,
+            this.performanceClient,
+            request.correlationId
+        )(request.account, foci);
 
         if (!refreshToken) {
             throw createInteractionRequiredAuthError(
@@ -274,11 +277,18 @@ export class RefreshTokenClient extends BaseClient {
 
         return invokeAsync(
             this.executePostToTokenEndpoint.bind(this),
-            PerformanceEvents.BaseClientExecutePostToTokenEndpoint,
+            PerformanceEvents.RefreshTokenClientExecutePostToTokenEndpoint,
             this.logger,
             this.performanceClient,
             request.correlationId
-        )(endpoint, requestBody, headers, thumbprint, request.correlationId);
+        )(
+            endpoint,
+            requestBody,
+            headers,
+            thumbprint,
+            request.correlationId,
+            PerformanceEvents.RefreshTokenClientExecutePostToTokenEndpoint
+        );
     }
 
     /**

lib/msal-common/src/client/SilentFlowClient.ts

@@ -25,6 +25,8 @@ import { IPerformanceClient } from "../telemetry/performance/IPerformanceClient"
 import { StringUtils } from "../utils/StringUtils";
 import { checkMaxAge, extractTokenClaims } from "../account/AuthToken";
 import { TokenClaims } from "../account/TokenClaims";
+import { PerformanceEvents } from "../telemetry/performance/PerformanceEvent";
+import { invokeAsync } from "../utils/FunctionWrappers";
 
 /** @internal */
 export class SilentFlowClient extends BaseClient {
@@ -92,6 +94,10 @@ export class SilentFlowClient extends BaseClient {
     async acquireCachedToken(
         request: CommonSilentFlowRequest
     ): Promise<[AuthenticationResult, CacheOutcome]> {
+        this.performanceClient?.addQueueMeasurement(
+            PerformanceEvents.SilentFlowClientAcquireCachedToken,
+            request.correlationId
+        );
         let lastCacheOutcome: CacheOutcome = CacheOutcome.NOT_APPLICABLE;
 
         // Cannot renew token if no request object is given.
@@ -101,26 +107,15 @@ export class SilentFlowClient extends BaseClient {
             );
         }
 
-        if (request.forceRefresh) {
-            // Must refresh due to present force_refresh flag.
-            lastCacheOutcome = CacheOutcome.FORCE_REFRESH_OR_CLAIMS;
-            this.serverTelemetryManager?.setCacheOutcome(
-                CacheOutcome.FORCE_REFRESH_OR_CLAIMS
-            );
-            this.logger.info(
-                "SilentFlowClient:acquireCachedToken - Skipping cache because forceRefresh is true."
-            );
-            throw createClientAuthError(
-                ClientAuthErrorCodes.tokenRefreshRequired
-            );
-        } else if (
-            !this.config.cacheOptions.claimsBasedCachingEnabled &&
-            !StringUtils.isEmptyObj(request.claims)
+        if (
+            request.forceRefresh ||
+            (!this.config.cacheOptions.claimsBasedCachingEnabled &&
+                !StringUtils.isEmptyObj(request.claims))
         ) {
-            lastCacheOutcome = CacheOutcome.FORCE_REFRESH_OR_CLAIMS;
-            // Must refresh due to request parameters.
-            this.logger.info(
-                "SilentFlowClient:acquireCachedToken - Skipping cache because claims-based caching is disabled and claims were requested."
+            // Must refresh due to present force_refresh flag.
+            this.setCacheOutcome(
+                CacheOutcome.FORCE_REFRESH_OR_CLAIMS,
+                request.correlationId
             );
             throw createClientAuthError(
                 ClientAuthErrorCodes.tokenRefreshRequired
@@ -145,12 +140,9 @@ export class SilentFlowClient extends BaseClient {
 
         if (!cacheRecord.accessToken) {
             // must refresh due to non-existent access_token
-            lastCacheOutcome = CacheOutcome.NO_CACHED_ACCESS_TOKEN;
-            this.serverTelemetryManager?.setCacheOutcome(
-                CacheOutcome.NO_CACHED_ACCESS_TOKEN
-            );
-            this.logger.info(
-                "SilentFlowClient:acquireCachedToken - No access token found in cache for the given properties."
+            this.setCacheOutcome(
+                CacheOutcome.NO_CACHED_ACCESS_TOKEN,
+                request.correlationId
             );
             throw createClientAuthError(
                 ClientAuthErrorCodes.tokenRefreshRequired
@@ -163,12 +155,9 @@ export class SilentFlowClient extends BaseClient {
             )
         ) {
             // must refresh due to the expires_in value
-            lastCacheOutcome = CacheOutcome.CACHED_ACCESS_TOKEN_EXPIRED;
-            this.serverTelemetryManager?.setCacheOutcome(
-                CacheOutcome.CACHED_ACCESS_TOKEN_EXPIRED
-            );
-            this.logger.info(
-                `SilentFlowClient:acquireCachedToken - Cached access token is expired or will expire within ${this.config.systemOptions.tokenRenewalOffsetSeconds} seconds.`
+            this.setCacheOutcome(
+                CacheOutcome.CACHED_ACCESS_TOKEN_EXPIRED,
+                request.correlationId
             );
             throw createClientAuthError(
                 ClientAuthErrorCodes.tokenRefreshRequired
@@ -179,26 +168,44 @@ export class SilentFlowClient extends BaseClient {
         ) {
             // must refresh (in the background) due to the refresh_in value
             lastCacheOutcome = CacheOutcome.PROACTIVELY_REFRESHED;
-            this.serverTelemetryManager?.setCacheOutcome(
-                CacheOutcome.PROACTIVELY_REFRESHED
-            );
-            this.logger.info(
-                "SilentFlowClient:acquireCachedToken - Cached access token's refreshOn property has been exceeded'."
-            );
 
             // don't throw ClientAuthError.createRefreshRequiredError(), return cached token instead
         }
 
+        this.setCacheOutcome(lastCacheOutcome, request.correlationId);
+
         if (this.config.serverTelemetryManager) {
             this.config.serverTelemetryManager.incrementCacheHits();
         }
 
         return [
-            await this.generateResultFromCacheRecord(cacheRecord, request),
+            await invokeAsync(
+                this.generateResultFromCacheRecord.bind(this),
+                PerformanceEvents.SilentFlowClientGenerateResultFromCacheRecord,
+                this.logger,
+                this.performanceClient,
+                request.correlationId
+            )(cacheRecord, request),
             lastCacheOutcome,
         ];
     }
 
+    private setCacheOutcome(
+        cacheOutcome: CacheOutcome,
+        correlationId: string
+    ): void {
+        this.serverTelemetryManager?.setCacheOutcome(cacheOutcome);
+        this.performanceClient?.addFields(
+            {
+                cacheOutcome: cacheOutcome,
+            },
+            correlationId
+        );
+        this.logger.info(
+            `Token refresh is required due to cache outcome: ${cacheOutcome}`
+        );
+    }
+
     /**
      * Helper function to build response object from the CacheRecord
      * @param cacheRecord
@@ -207,6 +214,10 @@ export class SilentFlowClient extends BaseClient {
         cacheRecord: CacheRecord,
         request: CommonSilentFlowRequest
     ): Promise<AuthenticationResult> {
+        this.performanceClient?.addQueueMeasurement(
+            PerformanceEvents.SilentFlowClientGenerateResultFromCacheRecord,
+            request.correlationId
+        );
         let idTokenClaims: TokenClaims | undefined;
         if (cacheRecord.idToken) {
             idTokenClaims = extractTokenClaims(

lib/msal-common/src/telemetry/performance/PerformanceEvent.ts

@@ -101,8 +101,10 @@ export const PerformanceEvents = {
     /**
      * Time spent sending/waiting for the response of a request to the token endpoint
      */
-    BaseClientExecutePostToTokenEndpoint:
-        "baseClientExecutePostToTokenEndpoint",
+    RefreshTokenClientExecutePostToTokenEndpoint:
+        "refreshTokenClientExecutePostToTokenEndpoint",
+    AuthorizationCodeClientExecutePostToTokenEndpoint:
+        "authorizationCodeClientExecutePostToTokenEndpoint",
     /**
      * Used to measure the time taken for completing embedded-broker handshake (PW-Broker).
      */
@@ -150,6 +152,9 @@ export const PerformanceEvents = {
      * Internal API for acquiring token from cache
      */
     AcquireTokenFromCache: "acquireTokenFromCache",
+    SilentFlowClientAcquireCachedToken: "silentFlowClientAcquireCachedToken",
+    SilentFlowClientGenerateResultFromCacheRecord:
+        "silentFlowClientGenerateResultFromCacheRecord",
 
     /**
      * acquireTokenBySilentIframe (msal-browser).
@@ -270,6 +275,7 @@ export const PerformanceEvents = {
      * Cache operations
      */
     ClearTokensAndKeysWithClaims: "clearTokensAndKeysWithClaims",
+    CacheManagerGetRefreshToken: "cacheManagerGetRefreshToken",
 
     /**
      * Crypto Operations
@@ -445,6 +451,12 @@ export type PerformanceEvent = {
      */
     cacheLookupPolicy?: number | undefined;
 
+    /**
+     * Cache Outcome
+     * @type {?number}
+     */
+    cacheOutcome?: number;
+
     /**
      * Amount of time spent in the JS queue in milliseconds.
      *