HybridCache: don't log cancellation as failure (#5601)

Author: mgravell

src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.StampedeStateT.cs

@@ -190,6 +190,15 @@ private async Task BackgroundFetchAsync()
                             }
                         }
                     }
+                    catch (OperationCanceledException) when (SharedToken.IsCancellationRequested)
+                    {
+                        if (eventSourceEnabled)
+                        {
+                            HybridCacheEventSource.Log.DistributedCacheCanceled();
+                        }
+
+                        throw; // don't just treat as miss - exit ASAP
+                    }
                     catch (Exception ex)
                     {
                         if (eventSourceEnabled)
@@ -227,11 +236,18 @@ private async Task BackgroundFetchAsync()
                             HybridCacheEventSource.Log.UnderlyingDataQueryComplete();
                         }
                     }
-                    catch
+                    catch (Exception ex)
                     {
                         if (eventSourceEnabled)
                         {
-                            HybridCacheEventSource.Log.UnderlyingDataQueryFailed();
+                            if (ex is OperationCanceledException && SharedToken.IsCancellationRequested)
+                            {
+                                HybridCacheEventSource.Log.UnderlyingDataQueryCanceled();
+                            }
+                            else
+                            {
+                                HybridCacheEventSource.Log.UnderlyingDataQueryFailed();
+                            }
                         }
 
                         throw;

src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/HybridCacheEventSource.cs

@@ -25,6 +25,8 @@ internal sealed class HybridCacheEventSource : EventSource
     internal const int EventIdLocalCacheWrite = 10;
     internal const int EventIdDistributedCacheWrite = 11;
     internal const int EventIdStampedeJoin = 12;
+    internal const int EventIdUnderlyingDataQueryCanceled = 13;
+    internal const int EventIdDistributedCacheCanceled = 14;
 
     // fast local counters
     private long _totalLocalCacheHit;
@@ -117,6 +119,14 @@ public void DistributedCacheFailed()
         WriteEvent(EventIdDistributedCacheFailed);
     }
 
+    [Event(EventIdDistributedCacheCanceled, Level = EventLevel.Verbose)]
+    public void DistributedCacheCanceled()
+    {
+        DebugAssertEnabled();
+        _ = Interlocked.Decrement(ref _currentDistributedFetch);
+        WriteEvent(EventIdDistributedCacheCanceled);
+    }
+
     [Event(EventIdUnderlyingDataQueryStart, Level = EventLevel.Verbose)]
     public void UnderlyingDataQueryStart()
     {
@@ -143,6 +153,14 @@ public void UnderlyingDataQueryFailed()
         WriteEvent(EventIdUnderlyingDataQueryFailed);
     }
 
+    [Event(EventIdUnderlyingDataQueryCanceled, Level = EventLevel.Verbose)]
+    public void UnderlyingDataQueryCanceled()
+    {
+        DebugAssertEnabled();
+        _ = Interlocked.Decrement(ref _currentUnderlyingDataQuery);
+        WriteEvent(EventIdUnderlyingDataQueryCanceled);
+    }
+
     [Event(EventIdLocalCacheWrite, Level = EventLevel.Verbose)]
     public void LocalCacheWrite()
     {

test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/HybridCacheEventSourceTests.cs

@@ -99,6 +99,19 @@ public async Task DistributedCacheFailed()
         listener.AssertRemainingCountersZero();
     }
 
+    [SkippableFact]
+    public async Task DistributedCacheCanceled()
+    {
+        AssertEnabled();
+
+        listener.Reset().Source.DistributedCacheGet();
+        listener.Reset(resetCounters: false).Source.DistributedCacheCanceled();
+        listener.AssertSingleEvent(HybridCacheEventSource.EventIdDistributedCacheCanceled, "DistributedCacheCanceled", EventLevel.Verbose);
+
+        await AssertCountersAsync();
+        listener.AssertRemainingCountersZero();
+    }
+
     [SkippableFact]
     public async Task UnderlyingDataQueryStart()
     {
@@ -141,6 +154,20 @@ public async Task UnderlyingDataQueryFailed()
         listener.AssertRemainingCountersZero();
     }
 
+    [SkippableFact]
+    public async Task UnderlyingDataQueryCanceled()
+    {
+        AssertEnabled();
+
+        listener.Reset().Source.UnderlyingDataQueryStart();
+        listener.Reset(resetCounters: false).Source.UnderlyingDataQueryCanceled();
+        listener.AssertSingleEvent(HybridCacheEventSource.EventIdUnderlyingDataQueryCanceled, "UnderlyingDataQueryCanceled", EventLevel.Verbose);
+
+        await AssertCountersAsync();
+        listener.AssertCounter("total-data-query", "Total Data Queries", 1);
+        listener.AssertRemainingCountersZero();
+    }
+
     [SkippableFact]
     public async Task LocalCacheWrite()
     {

test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/TestEventListener.cs

@@ -50,7 +50,7 @@ protected override void OnEventSourceCreated(EventSource eventSource)
             {
                 ["EventCounterIntervalSec"] = EventCounterIntervalSec.ToString("G", CultureInfo.InvariantCulture),
             };
-            EnableEvents(Source, EventLevel.Verbose, EventKeywords.All, args);
+            EnableEvents(Source, EventLevel.LogAlways, EventKeywords.All, args);
         }
 
         base.OnEventSourceCreated(eventSource);