diff --git a/src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapter.cs b/src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapter.cs index efb6dc991..ac5ff06ec 100644 --- a/src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapter.cs +++ b/src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapter.cs @@ -70,19 +70,13 @@ public MsalDistributedTokenCacheAdapter( /// A that completes when key removal has completed. 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); } /// @@ -94,24 +88,22 @@ protected override async Task RemoveKeyAsync(string cacheKey) /// (account or app). protected override async Task 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 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 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 L2OperationWithRetryOnFailureAsync( + string operation, + Func> 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; } } } diff --git a/src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapterOptions.cs b/src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapterOptions.cs index b15933f1c..42e202d47 100644 --- a/src/Microsoft.Identity.Web/TokenCacheProviders/Distributed/MsalDistributedTokenCacheAdapterOptions.cs +++ b/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 /// public long L1CacheSizeLimit { get; set; } = 500; + /// + /// 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 true if the cache should try again the operation, and + /// false otherwise. When true is passed and the retry fails, an exception + /// will be thrown. + /// + public Func? OnL2CacheFailure { get; set; } + /// /// Value more than 0, less than 1, to set the In Memory (L1) cache /// expiration time values relative to the Distributed (L2) cache. diff --git a/tests/WebAppCallsWebApiCallsGraph/Client/Startup.cs b/tests/WebAppCallsWebApiCallsGraph/Client/Startup.cs index a6952921f..3a90a194e 100644 --- a/tests/WebAppCallsWebApiCallsGraph/Client/Startup.cs +++ b/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(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)