Merge pull request #901 from AzureAD/avdunn/cache-refresh-metadata

Add CacheRefreshReason to telemetry and metadata

Author: Avery-Dunn

msal4j-sdk/src/main/java/com/microsoft/aad/msal4j/AcquireTokenSilentSupplier.java

@@ -57,7 +57,7 @@ AuthenticationResult execute() throws Exception {
 
             shouldRefresh = shouldRefresh(silentRequest.parameters(), res);
 
-            if (shouldRefresh || clientApplication.serviceBundle().getServerSideTelemetry().getCurrentRequest().cacheInfo() == CacheTelemetry.REFRESH_REFRESH_IN.telemetryValue) {
+            if (shouldRefresh) {
                 if (!StringHelper.isBlank(res.refreshToken())) {
                     //There are certain scenarios where the cached authority may differ from the client app's authority,
                     // such as when a request is instance aware. Unless overridden by SilentParameters.authorityUrl, the
@@ -66,7 +66,8 @@ AuthenticationResult execute() throws Exception {
                         requestAuthority = Authority.createAuthority(new URL(requestAuthority.authority().replace(requestAuthority.host(),
                                 res.account().environment())));
                     }
-                    res = makeRefreshRequest(res, requestAuthority);
+
+                    res = makeRefreshRequest(res, requestAuthority, clientApplication.serviceBundle().getServerSideTelemetry().getCurrentRequest().cacheInfo());
                 } else {
                     res = null;
                 }
@@ -81,27 +82,32 @@ AuthenticationResult execute() throws Exception {
         return res;
     }
 
-    private AuthenticationResult makeRefreshRequest(AuthenticationResult cachedResult,  Authority requestAuthority) throws Exception {
+    private AuthenticationResult makeRefreshRequest(AuthenticationResult cachedResult, Authority requestAuthority, CacheRefreshReason refreshReason) throws Exception {
+
         RefreshTokenRequest refreshTokenRequest = new RefreshTokenRequest(
                 RefreshTokenParameters.builder(silentRequest.parameters().scopes(), cachedResult.refreshToken()).build(),
                 silentRequest.application(),
                 silentRequest.requestContext(),
                 silentRequest);
 
+        //The ServiceBundle will have a new CurrentRequest object when the RefreshTokenRequest is made, so the telemetry value needs to be set again
+        setCacheTelemetry(refreshReason);
+
         AcquireTokenByAuthorizationGrantSupplier acquireTokenByAuthorisationGrantSupplier =
                 new AcquireTokenByAuthorizationGrantSupplier(clientApplication, refreshTokenRequest, requestAuthority);
 
         try {
             AuthenticationResult refreshedResult = acquireTokenByAuthorisationGrantSupplier.execute();
 
             refreshedResult.metadata().tokenSource(TokenSource.IDENTITY_PROVIDER);
+            refreshedResult.metadata().cacheRefreshReason(refreshReason);
 
             log.info("Access token refreshed successfully.");
             return refreshedResult;
         } catch (MsalServiceException ex) {
             //If the token refresh attempt threw a MsalServiceException but the refresh attempt was done
             // only because of refreshOn, then simply return the existing cached token rather than throw an exception
-            if (clientApplication.serviceBundle().getServerSideTelemetry().getCurrentRequest().cacheInfo() == CacheTelemetry.REFRESH_REFRESH_IN.telemetryValue) {
+            if (refreshReason == CacheRefreshReason.PROACTIVE_REFRESH) {
                 return cachedResult;
             }
             throw ex;
@@ -113,48 +119,48 @@ private boolean shouldRefresh(SilentParameters parameters, AuthenticationResult
 
         //If forceRefresh is true, no reason to check any other option
         if (parameters.forceRefresh()) {
-            setCacheTelemetry(CacheTelemetry.REFRESH_FORCE_REFRESH.telemetryValue);
-            log.debug("Refreshing access token because forceRefresh parameter is true.");
+            setCacheTelemetry(CacheRefreshReason.FORCE_REFRESH);
+            log.debug(String.format("Refreshing access token. Cache refresh reason: %s", CacheRefreshReason.FORCE_REFRESH));
             return true;
         }
 
         //If the request contains claims then the token should be refreshed, to ensure that the returned token has the correct claims
         //  Note: these are the types of claims found in (for example) a claims challenge, and do not include client capabilities
         if (parameters.claims() != null) {
-            setCacheTelemetry(CacheTelemetry.REFRESH_FORCE_REFRESH.telemetryValue);
-            log.debug("Refreshing access token because the claims parameter is not null.");
+            setCacheTelemetry(CacheRefreshReason.CLAIMS);
+            log.debug(String.format("Refreshing access token. Cache refresh reason: %s", CacheRefreshReason.CLAIMS));
             return true;
         }
 
         long currTimeStampSec = new Date().getTime() / 1000;
 
         //If the access token is expired or within 5 minutes of becoming expired, refresh it
         if (!StringHelper.isBlank(cachedResult.accessToken()) && cachedResult.expiresOn() < (currTimeStampSec + ACCESS_TOKEN_EXPIRE_BUFFER_IN_SEC)) {
-            setCacheTelemetry(CacheTelemetry.REFRESH_ACCESS_TOKEN_EXPIRED.telemetryValue);
-            log.debug("Refreshing access token because it is expired.");
+            setCacheTelemetry(CacheRefreshReason.EXPIRED);
+            log.debug(String.format("Refreshing access token. Cache refresh reason: %s", CacheRefreshReason.EXPIRED));
             return true;
         }
 
         //Certain long-lived tokens will have a 'refresh on' time that indicates a refresh should be attempted long before the token would expire
         if (!StringHelper.isBlank(cachedResult.accessToken()) &&
                 cachedResult.refreshOn() != null && cachedResult.refreshOn() > 0 &&
                 cachedResult.refreshOn() < currTimeStampSec && cachedResult.expiresOn() >= (currTimeStampSec + ACCESS_TOKEN_EXPIRE_BUFFER_IN_SEC)){
-            setCacheTelemetry(CacheTelemetry.REFRESH_REFRESH_IN.telemetryValue);
-            log.debug("Attempting to refresh access token because it is after the refreshOn time.");
+            setCacheTelemetry(CacheRefreshReason.PROACTIVE_REFRESH);
+            log.debug(String.format("Refreshing access token. Cache refresh reason: %s", CacheRefreshReason.PROACTIVE_REFRESH));
             return true;
         }
 
         //If there is a refresh token but no access token, we should use the refresh token to get the access token
         if (StringHelper.isBlank(cachedResult.accessToken()) && !StringHelper.isBlank(cachedResult.refreshToken())) {
-            setCacheTelemetry(CacheTelemetry.REFRESH_NO_ACCESS_TOKEN.telemetryValue);
-            log.debug("Refreshing access token because it was missing from the cache.");
+            setCacheTelemetry(CacheRefreshReason.NO_CACHED_ACCESS_TOKEN);
+            log.debug(String.format("Refreshing access token. Cache refresh reason: %s", CacheRefreshReason.NO_CACHED_ACCESS_TOKEN));
             return true;
         }
 
         return false;
     }
 
-    private void setCacheTelemetry(int cacheInfoValue){
+    private void setCacheTelemetry(CacheRefreshReason cacheInfoValue){
         clientApplication.serviceBundle().getServerSideTelemetry().getCurrentRequest().cacheInfo(cacheInfoValue);
     }
 }

msal4j-sdk/src/main/java/com/microsoft/aad/msal4j/AuthenticationResultMetadata.java

@@ -20,6 +20,19 @@
 @Builder
 public class AuthenticationResultMetadata implements Serializable {
 
+    /**
+     * The source of the tokens in the {@link AuthenticationResult}, see {@link TokenSource} for possible values
+     */
     private TokenSource tokenSource;
+
+    /**
+     * When the token should be proactively refreshed. May be null or 0 if proactive refresh is not used
+     */
     private Long refreshOn;
+
+    /**
+     * Specifies the reason for refreshing the access token, see {@link CacheRefreshReason} for possible values. Will be {@link CacheRefreshReason#NOT_APPLICABLE} if the token was returned from the cache or if the API used to fetch the token does not attempt to read the cache.
+     */
+    @Builder.Default
+    private CacheRefreshReason cacheRefreshReason = CacheRefreshReason.NOT_APPLICABLE;
 }

msal4j-sdk/src/main/java/com/microsoft/aad/msal4j/CacheRefreshReason.java

@@ -0,0 +1,40 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+package com.microsoft.aad.msal4j;
+
+/**
+ * Specifies the reason for fetching the access token from the identity provider when using {@link AbstractClientApplicationBase#acquireTokenSilently(SilentParameters)}
+ */
+public enum CacheRefreshReason {
+    /**
+     * Token did not need to be refreshed, or was retrieved in a non-silent call
+     */
+    NOT_APPLICABLE(0),
+    /**
+     * Silent call was made with the force refresh option
+     */
+    FORCE_REFRESH(1),
+    /**
+     * Silent call was made with claims set
+     */
+    CLAIMS(1),
+    /**
+     * Access token was missing from the cache, but a valid refresh token was used to retrieve a new access token
+     */
+    NO_CACHED_ACCESS_TOKEN(2),
+    /**
+     * Cached access token was expired and successfully refreshed
+     */
+    EXPIRED(3),
+    /**
+     * Cached access token was not expired but was after the 'refresh_in' value, and was proactively refreshed before the expiration date
+     */
+    PROACTIVE_REFRESH(4);
+
+    final int telemetryValue;
+
+    CacheRefreshReason(int telemetryValue) {
+        this.telemetryValue = telemetryValue;
+    }
+}

msal4j-sdk/src/main/java/com/microsoft/aad/msal4j/CacheTelemetry.java

@@ -14,7 +14,7 @@ class CurrentRequest {
     private final PublicApi publicApi;
 
     @Setter
-    private int cacheInfo = -1;
+    private CacheRefreshReason cacheInfo = CacheRefreshReason.NOT_APPLICABLE;
 
     @Setter
     private String regionUsed = StringHelper.EMPTY_STRING;

msal4j-sdk/src/main/java/com/microsoft/aad/msal4j/CurrentRequest.java

@@ -67,7 +67,7 @@ private synchronized String buildCurrentRequestHeader() {
         String currentRequestHeader = SCHEMA_VERSION + SCHEMA_PIPE_DELIMITER +
                 currentRequest.publicApi().getApiId() +
                 SCHEMA_COMMA_DELIMITER +
-                (currentRequest.cacheInfo() == -1 ? "" : currentRequest.cacheInfo()) +
+                currentRequest.cacheInfo().telemetryValue +
                 SCHEMA_COMMA_DELIMITER +
                 currentRequest.regionUsed() +
                 SCHEMA_COMMA_DELIMITER +

msal4j-sdk/src/main/java/com/microsoft/aad/msal4j/ServerSideTelemetry.java

@@ -32,7 +32,7 @@ class SilentRequest extends MsalRequest {
 
         if (parameters.forceRefresh()) {
             application.serviceBundle().getServerSideTelemetry().getCurrentRequest().cacheInfo(
-                    CacheTelemetry.REFRESH_FORCE_REFRESH.telemetryValue);
+                    CacheRefreshReason.FORCE_REFRESH);
         }
     }
 }

msal4j-sdk/src/main/java/com/microsoft/aad/msal4j/SilentRequest.java

@@ -11,14 +11,17 @@
 import static org.junit.jupiter.api.Assertions.assertNotNull;
 import static org.junit.jupiter.api.Assertions.assertEquals;
 import static org.junit.jupiter.api.Assertions.assertInstanceOf;
+import static org.mockito.Mockito.*;
 
 import java.io.IOException;
 import java.net.URISyntaxException;
 import java.nio.file.Files;
 import java.nio.file.Paths;
 import java.util.Collections;
+import java.util.HashMap;
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.ExecutionException;
+import java.util.concurrent.TimeUnit;
 
 
 @TestInstance(TestInstance.Lifecycle.PER_CLASS)
@@ -116,6 +119,97 @@ void confidentialAppAcquireTokenSilently_claimsSkipCache() throws Throwable {
         assertInstanceOf(MsalInteractionRequiredException.class, ex.getCause());
     }
 
+    @Test
+    void testTokenRefreshReasons() throws Exception {
+        DefaultHttpClient httpClientMock = mock(DefaultHttpClient.class);
+
+        ConfidentialClientApplication cca =
+                ConfidentialClientApplication.builder("clientId", ClientCredentialFactory.createFromSecret("password"))
+                        .authority("https://login.microsoftonline.com/tenant/")
+                        .instanceDiscovery(false)
+                        .validateAuthority(false)
+                        .httpClient(httpClientMock)
+                        .build();
+
+        HashMap<String, String> responseParameters = new HashMap<>();
+
+        //Acquire a token that expires at the same time it is acquired, so it will expire before the next acquire token call
+        responseParameters.put("access_token", "expiredToken");
+        responseParameters.put("id_token", TestHelper.createIdToken(new HashMap<>()));
+        responseParameters.put("expires_in", "0");
+        TestHelper.createTokenRequestMock(httpClientMock, TestHelper.getSuccessfulTokenResponse(responseParameters), 200);
+
+        OnBehalfOfParameters parameters = OnBehalfOfParameters.builder(Collections.singleton("someScopes"), new UserAssertion(TestHelper.signedAssertion)).build();
+        IAuthenticationResult result = cca.acquireToken(parameters).get();
+
+        //There should be one token in the cache, and no refresh behavior should have happened yet
+        assertRefreshedToken(result, "expiredToken", CacheRefreshReason.NOT_APPLICABLE, cca.tokenCache.accessTokens.size());
+
+        //Attempt to retrieve the cached token, however it is expired and should be refreshed.
+        // In this test, it will be replaced with a token that expires in 1 minute
+        responseParameters.put("access_token", "nearlyExpiredToken");
+        responseParameters.put("expires_in", "60");
+        TestHelper.createTokenRequestMock(httpClientMock, TestHelper.getSuccessfulTokenResponse(responseParameters), 200);
+
+        SilentParameters silentParameters = SilentParameters.builder(Collections.singleton("someScopes"), result.account()).build();
+        result = cca.acquireTokenSilently(silentParameters).get();
+
+        //Ensure there is still one token in the cache, however it is the new refreshed token rather than the token from the first mocked call
+        assertRefreshedToken(result, "nearlyExpiredToken", CacheRefreshReason.EXPIRED, cca.tokenCache.accessTokens.size());
+
+        //Attempt to retrieve the cached token, however it is within the 5-minute buffer and should be refreshed.
+        // In this test, it will be replaced with a token that expires in 1 hour but has a refresh_in time of 1 second
+        responseParameters.put("access_token", "refreshInToken");
+        responseParameters.put("expires_in", "3600");
+        responseParameters.put("refresh_in", "1");
+        TestHelper.createTokenRequestMock(httpClientMock, TestHelper.getSuccessfulTokenResponse(responseParameters), 200);
+
+        silentParameters = SilentParameters.builder(Collections.singleton("someScopes"), result.account()).build();
+        result = cca.acquireTokenSilently(silentParameters).get();
+
+        assertRefreshedToken(result, "refreshInToken", CacheRefreshReason.EXPIRED, cca.tokenCache.accessTokens.size());
+
+        //Attempt to retrieve the cached token, however it is within the 5-minute buffer and should be refreshed.
+        // In this test, it will be replaced with a token that expires in 1 hour (and does not have a valid refresh_in time)
+        responseParameters.put("access_token", "normalToken");
+        responseParameters.put("expires_in", "3600");
+        responseParameters.put("refresh_in", "0");
+        TestHelper.createTokenRequestMock(httpClientMock, TestHelper.getSuccessfulTokenResponse(responseParameters), 200);
+
+        //refresh_in values are in seconds, so we must wait to guarantee it is past the proactive refresh time
+        TimeUnit.SECONDS.sleep(2);
+
+        silentParameters = SilentParameters.builder(Collections.singleton("someScopes"), result.account()).build();
+        result = cca.acquireTokenSilently(silentParameters).get();
+
+        assertRefreshedToken(result, "normalToken", CacheRefreshReason.PROACTIVE_REFRESH, cca.tokenCache.accessTokens.size());
+
+        //Force the token to be refreshed
+        responseParameters.put("access_token", "forcedRefreshToken");
+        TestHelper.createTokenRequestMock(httpClientMock, TestHelper.getSuccessfulTokenResponse(responseParameters), 200);
+
+        silentParameters = SilentParameters.builder(Collections.singleton("someScopes"), result.account()).forceRefresh(true).build();
+        result = cca.acquireTokenSilently(silentParameters).get();
+
+        assertRefreshedToken(result, "forcedRefreshToken", CacheRefreshReason.FORCE_REFRESH, cca.tokenCache.accessTokens.size());
+
+        //Finally, force a refresh by setting claims
+        responseParameters.put("access_token", "claimsToken");
+        TestHelper.createTokenRequestMock(httpClientMock, TestHelper.getSuccessfulTokenResponse(responseParameters), 200);
+
+        silentParameters = SilentParameters.builder(Collections.singleton("someScopes"), result.account()).claims(new ClaimsRequest()).build();
+        result = cca.acquireTokenSilently(silentParameters).get();
+
+        assertRefreshedToken(result, "claimsToken", CacheRefreshReason.CLAIMS, cca.tokenCache.accessTokens.size());
+    }
+
+    //Asserts that there is one expected token in the cache, and that it was refreshed with the expected reason
+    private void assertRefreshedToken(IAuthenticationResult result, String expectedToken, CacheRefreshReason expectedReason, int cacheSize) {
+        assertEquals(1, cacheSize);
+        assertEquals(expectedToken, result.accessToken());
+        assertEquals(expectedReason, result.metadata().cacheRefreshReason());
+    }
+
     String readResource(String resource) {
         try {
             return new String(Files.readAllBytes(Paths.get(getClass().getResource(resource).toURI())));