L2 Cache retry initial commit

src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapter.cs

@@ -70,19 +70,13 @@ public MsalDistributedTokenCacheAdapter(
         /// <returns>A <see cref="Task"/> that completes when key removal has completed.</returns>
         protected override async Task RemoveKeyAsync(string cacheKey)
         {
-            var startTicks = Utility.Watch.Elapsed.Ticks;
             _memoryCache.Remove(cacheKey);
-            _logger.LogDebug($"[IdWebCache] MemoryCache: Remove cacheKey {cacheKey} Time in Ticks: {Utility.Watch.Elapsed.Ticks - startTicks}. ");
+            _logger.LogDebug($"[MsIdWeb] MemoryCache: Removed cacheKey {cacheKey}. ");
 
-            try
-            {
-                await _distributedCache.RemoveAsync(cacheKey).ConfigureAwait(false);
-                _logger.LogDebug($"[IdWebCache] DistributedCache: Remove cacheKey {cacheKey} Time in Ticks: {Utility.Watch.Elapsed.Ticks - startTicks}. ");
-            }
-            catch (Exception ex)
-            {
-                _logger.LogError($"[IdWebCache] Connection issue encountered with Distributed cache. Currently using In Memory cache only. Error message: {ex.Message} ");
-            }
+            await L2OperationWithRetryOnFailureAsync(
+                "Removed",
+                (cacheKey) => _distributedCache.RemoveAsync(cacheKey),
+                cacheKey).ConfigureAwait(false);
         }
 
         /// <summary>
@@ -94,24 +88,22 @@ protected override async Task RemoveKeyAsync(string cacheKey)
         /// (account or app).</returns>
         protected override async Task<byte[]> ReadCacheBytesAsync(string cacheKey)
         {
-            var startTicks = Utility.Watch.Elapsed.Ticks;
-
             // check memory cache first
-            byte[] result = (byte[])_memoryCache.Get(cacheKey);
-            _logger.LogDebug($"[IdWebCache] MemoryCache: Read cache {cacheKey} Byte size: {result?.Length}. ");
+            byte[]? result = (byte[])_memoryCache.Get(cacheKey);
+            _logger.LogDebug($"[MsIdWeb] MemoryCache: Read {cacheKey} cache size: {result?.Length}. ");
 
             if (result == null)
             {
-                // not found in memory, check distributed cache
-                try
-                {
-                    result = await _distributedCache.GetAsync(cacheKey).ConfigureAwait(false);
-                    _logger.LogDebug($"[IdWebCache] DistributedCache read: No result in memory, distributed cache result - Byte size: {result?.Length}. ");
-                }
-                catch (Exception ex)
+                var measure = await Task.Run(async () =>
                 {
-                    _logger.LogError($"[IdWebCache] Connection issue encountered with Distributed cache. Currently using In Memory cache only. Error message: {ex.Message} ");
-                }
+                    // not found in memory, check distributed cache
+                    result = await L2OperationWithRetryOnFailureAsync(
+                        "Read",
+                        (cacheKey) => _distributedCache.GetAsync(cacheKey),
+                        cacheKey).ConfigureAwait(false);
+                }).Measure().ConfigureAwait(false);
+
+                _logger.LogDebug($"[MsIdWeb] DistributedCache: Read time in Ticks: {measure.Ticks}");
 
                 // back propagate to memory cache
                 if (result != null)
@@ -122,13 +114,12 @@ protected override async Task<byte[]> ReadCacheBytesAsync(string cacheKey)
                         Size = result?.Length,
                     };
 
-                    _logger.LogDebug($"[IdWebCache] Back propagate from Distributed to Memory, Byte size: {result?.Length}");
+                    _logger.LogDebug($"[MsIdWeb] Back propagate from Distributed to Memory, cache size: {result?.Length}");
                     _memoryCache.Set(cacheKey, result, memoryCacheEntryOptions);
-                    _logger.LogDebug($"[IdWebCache] MemoryCache: Count: {_memoryCache.Count}");
+                    _logger.LogDebug($"[MsIdWeb] MemoryCache: Count: {_memoryCache.Count}");
                 }
             }
 
-            _logger.LogDebug($"[IdWebCache] Read caches for {cacheKey} returned Bytes {result?.Length} Time in Ticks: {Utility.Watch.Elapsed.Ticks - startTicks}. ");
 #pragma warning disable CS8603 // Possible null reference return.
             return result;
 #pragma warning restore CS8603 // Possible null reference return.
@@ -149,21 +140,73 @@ protected override async Task WriteCacheBytesAsync(string cacheKey, byte[] bytes
             };
 
             // write in both
-            var startTicks = Utility.Watch.Elapsed.Ticks;
-
             _memoryCache.Set(cacheKey, bytes, memoryCacheEntryOptions);
-            _logger.LogDebug($"[IdWebCache] MemoryCache: Write cacheKey {cacheKey} Byte size: {bytes?.Length} Time in Ticks: {Utility.Watch.Elapsed.Ticks - startTicks}. ");
-            _logger.LogDebug($"[IdWebCache] MemoryCache: Count: {_memoryCache.Count}");
+            _logger.LogDebug($"[MsIdWeb] MemoryCache: Write cacheKey {cacheKey} cache size: {bytes?.Length}. ");
+            _logger.LogDebug($"[MsIdWeb] MemoryCache: Count: {_memoryCache.Count}");
+
+            var measure = await L2OperationWithRetryOnFailureAsync(
+                "Write",
+                (cacheKey) => _distributedCache.SetAsync(cacheKey, bytes, _distributedCacheOptions),
+                cacheKey).Measure().ConfigureAwait(false);
+        }
+
+        private async Task L2OperationWithRetryOnFailureAsync(
+            string operation,
+            Func<string, Task> cacheOperation,
+            string cacheKey,
+            byte[]? bytes = null,
+            bool inRetry = false)
+        {
+            try
+            {
+                var measure = await cacheOperation(cacheKey).Measure().ConfigureAwait(false);
+                _logger.LogDebug($"[MsIdWeb] DistributedCache: {operation} cacheKey {cacheKey} cache size {bytes?.Length} InRetry? {inRetry} Time in Ticks: {measure.Ticks}. ");
+            }
+            catch (Exception ex)
+            {
+                _logger.LogError($"[MsIdWeb] DistributedCache: Connection issue. InRetry? {inRetry} Error message: {ex.Message} ");
+
+                if (_distributedCacheOptions.OnL2CacheFailure != null && _distributedCacheOptions.OnL2CacheFailure(ex) && !inRetry)
+                {
+                    _logger.LogDebug($"[MsIdWeb] DistributedCache: Retrying {operation} cacheKey {cacheKey}. ");
+                    await L2OperationWithRetryOnFailureAsync(
+                        operation,
+                        cacheOperation,
+                        cacheKey,
+                        bytes,
+                        true).ConfigureAwait(false);
+                }
+            }
+        }
 
+        private async Task<byte[]?> L2OperationWithRetryOnFailureAsync(
+            string operation,
+            Func<string, Task<byte[]>> cacheOperation,
+            string cacheKey,
+            bool inRetry = false)
+        {
+            byte[]? result = null;
             try
             {
-                await _distributedCache.SetAsync(cacheKey, bytes, _distributedCacheOptions).ConfigureAwait(false);
-                _logger.LogDebug($"[IdWebCache] DistributedCache: Write cacheKey {cacheKey} Byte size {bytes?.Length} Time in Ticks: {Utility.Watch.Elapsed.Ticks - startTicks}. ");
+                result = await cacheOperation(cacheKey).ConfigureAwait(false);
+                _logger.LogDebug($"[MsIdWeb] DistributedCache: {operation} cacheKey {cacheKey} cache size {result?.Length} InRetry? {inRetry}. ");
             }
             catch (Exception ex)
             {
-                _logger.LogError($"[IdWebCache] Connection issue encountered with Distributed cache. Currently using In Memory cache only. Error message: {ex.Message} ");
+                _logger.LogError($"[MsIdWeb] DistributedCache: Connection issue. InRetry? {inRetry} Error message: {ex.Message} ");
+
+                if (_distributedCacheOptions.OnL2CacheFailure != null && _distributedCacheOptions.OnL2CacheFailure(ex) && !inRetry)
+                {
+                    _logger.LogDebug($"[MsIdWeb] DistributedCache: Retrying {operation} cacheKey {cacheKey}. ");
+                    result = await L2OperationWithRetryOnFailureAsync(
+                        operation,
+                        cacheOperation,
+                        cacheKey,
+                        true).ConfigureAwait(false);
+                }
             }
+
+            return result;
         }
     }
 }

src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapterOptions.cs

@@ -1,6 +1,7 @@
 // Copyright (c) Microsoft Corporation. All rights reserved.
 // Licensed under the MIT License.
 
+using System;
 using Microsoft.Extensions.Caching.Distributed;
 
 namespace Microsoft.Identity.Web.TokenCacheProviders.Distributed
@@ -18,6 +19,17 @@ public class MsalDistributedTokenCacheAdapterOptions : DistributedCacheEntryOpti
         /// </summary>
         public long L1CacheSizeLimit { get; set; } = 500;
 
+        /// <summary>
+        /// Callback offered to the app to be notified when the L2 cache fails.
+        /// This way the app is given the possibility to act on the L2 cache,
+        /// for instance, in the case of Redis, to reconnect. This is left to the application as it's
+        /// the only one that knows about the real implementation of the L2 cache.
+        /// The handler should return <c>true</c> if the cache should try again the operation, and
+        /// <c>false</c> otherwise. When <c>true</c> is passed and the retry fails, an exception
+        /// will be thrown.
+        /// </summary>
+        public Func<Exception, bool>? OnL2CacheFailure { get; set; }
+
         /// <summary>
         /// Value more than 0, less than 1, to set the In Memory (L1) cache
         /// expiration time values relative to the Distributed (L2) cache.

tests/WebAppCallsWebApiCallsGraph/Client/Startup.cs

@@ -14,6 +14,7 @@
 using Microsoft.Extensions.Hosting;
 using Microsoft.AspNetCore.Authentication.OpenIdConnect;
 using Microsoft.Identity.Web.UI;
+using Microsoft.Identity.Web.TokenCacheProviders.Distributed;
 
 namespace WebApp_OpenIDConnect_DotNet
 {
@@ -48,6 +49,18 @@ public void ConfigureServices(IServiceCollection services)
                 options.Configuration = Configuration.GetConnectionString("Redis");
                 options.InstanceName = "RedisDemos_"; //should be unique to the app
             });
+            services.Configure<MsalDistributedTokenCacheAdapterOptions>(options => 
+            {
+                options.OnL2CacheFailure = (ex) =>
+                {
+                    if (ex is StackExchange.Redis.RedisConnectionException)
+                    {
+                        // action: try to reconnect or something
+                        return true; //try to do the cache operation again
+                    }
+                    return false;
+                };
+            });
 #endif
 
             services.AddAuthentication(OpenIdConnectDefaults.AuthenticationScheme)