HybridCache stability and logging improvements (#5467)

* - handle serialization failures
- enforce payload quota
- enforce key validity
- add proper logging (infrastructure failure: needs attn)

# Conflicts:
#	src/Libraries/Microsoft.Extensions.Caching.Hybrid/Microsoft.Extensions.Caching.Hybrid.csproj

* - add "callback" to .dic
- log deserialization failures
- expose serialization failures
- tests for serialization logging scenarios

* support and tests for stability despite unreliable L2

* nit

* Compile for NS2.0

* include enabled check in our log output

* add event-source tracing and counters

* explicitly specify event-source guid

* satisfy the stylebot overloads

* nix SDT

* fix failing CI test

* limit to net462

* PR feedback (all except event tests)

* naming

* add event source tests

* fix redundant comment

* add clarification

* more clarifications

* dance for our robot overlords

* drop Microsoft.Extensions.Telemetry.Abstractions package-ref

* fix glitchy L2 test

* better tracking for invalid event-source state

* reserve non-printable characters from keys, to prevent L2 abuse

* improve test output for ETW

* tyop

* ETW tests: allow longer if needed

* whitespace

* more ETW fixins

---------

Co-authored-by: Jose Perez Rodriguez <joperezr@microsoft.com>

eng/packages/TestOnly.props

@@ -7,6 +7,7 @@
     <PackageVersion Include="BenchmarkDotNet" Version="0.13.5" />
     <PackageVersion Include="FluentAssertions" Version="6.11.0" />
     <PackageVersion Include="Grpc.AspNetCore" Version="2.65.0" />
+    <PackageVersion Include="JsonSchema.Net" Version="7.2.3" />
     <PackageVersion Include="Microsoft.Data.SqlClient" Version="5.2.2" />
     <PackageVersion Include="Microsoft.Diagnostics.Tracing.TraceEvent" Version="3.1.3" />
     <PackageVersion Include="Microsoft.ML.Tokenizers" Version="0.22.0-preview.24378.1" />
@@ -20,7 +21,7 @@
     <PackageVersion Include="Verify.Xunit" Version="20.4.0" />
     <PackageVersion Include="Xunit.Combinatorial" Version="1.6.24" />
     <PackageVersion Include="xunit.extensibility.execution" Version="2.4.2" />
-    <PackageVersion Include="JsonSchema.Net" Version="7.2.3" />
+    <PackageVersion Include="Xunit.SkippableFact" Version="1.4.13" />
   </ItemGroup>
 
   <ItemGroup Condition="'$(TargetFramework)' == 'net462'">

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

@@ -5,6 +5,7 @@
 using System.Diagnostics;
 using System.Threading;
 using Microsoft.Extensions.Caching.Memory;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.Extensions.Caching.Hybrid.Internal;
 
@@ -22,7 +23,7 @@ internal abstract class CacheItem
         // zero.
         // This counter also drives cache lifetime, with the cache itself incrementing the count by one. In the
         // case of mutable data, cache eviction may reduce this to zero (in cooperation with any concurrent readers,
-        // who incr/decr around their fetch), allowing safe buffer recycling.
+        // who increment/decrement around their fetch), allowing safe buffer recycling.
 
         internal int RefCount => Volatile.Read(ref _refCount);
 
@@ -89,13 +90,18 @@ internal abstract class CacheItem<T> : CacheItem
     {
         public abstract bool TryGetSize(out long size);
 
-        // attempt to get a value that was *not* previously reserved
-        public abstract bool TryGetValue(out T value);
+        // Attempt to get a value that was *not* previously reserved.
+        // Note on ILogger usage: we don't want to propagate and store this everywhere.
+        // It is used for reporting deserialization problems - pass it as needed.
+        // (CacheItem gets into the IMemoryCache - let's minimize the onward reachable set
+        // of that cache, by only handing it leaf nodes of a "tree", not a "graph" with
+        // backwards access - we can also limit object size at the same time)
+        public abstract bool TryGetValue(ILogger log, out T value);
 
         // get a value that *was* reserved, countermanding our reservation in the process
-        public T GetReservedValue()
+        public T GetReservedValue(ILogger log)
         {
-            if (!TryGetValue(out var value))
+            if (!TryGetValue(log, out var value))
             {
                 Throw();
             }

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

@@ -2,6 +2,7 @@
 // The .NET Foundation licenses this file to you under the MIT license.
 
 using System.Threading;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.Extensions.Caching.Hybrid.Internal;
 
@@ -38,7 +39,7 @@ public void SetValue(T value, long size)
             Size = size;
         }
 
-        public override bool TryGetValue(out T value)
+        public override bool TryGetValue(ILogger log, out T value)
         {
             value = _value;
             return true; // always available

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

@@ -16,12 +16,16 @@ internal partial class DefaultHybridCache
 {
     [SuppressMessage("Performance", "CA1849:Call async methods when in an async method", Justification = "Manual sync check")]
     [SuppressMessage("Usage", "VSTHRD003:Avoid awaiting foreign Tasks", Justification = "Manual sync check")]
+    [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "Explicit async exception handling")]
+    [SuppressMessage("Reliability", "CA2000:Dispose objects before losing scope", Justification = "Deliberate recycle only on success")]
     internal ValueTask<BufferChunk> GetFromL2Async(string key, CancellationToken token)
     {
         switch (GetFeatures(CacheFeatures.BackendCache | CacheFeatures.BackendBuffers))
         {
             case CacheFeatures.BackendCache: // legacy byte[]-based
+
                 var pendingLegacy = _backendCache!.GetAsync(key, token);
+
 #if NETCOREAPP2_0_OR_GREATER || NETSTANDARD2_1_OR_GREATER
                 if (!pendingLegacy.IsCompletedSuccessfully)
 #else
@@ -36,6 +40,7 @@ internal ValueTask<BufferChunk> GetFromL2Async(string key, CancellationToken tok
             case CacheFeatures.BackendCache | CacheFeatures.BackendBuffers: // IBufferWriter<byte>-based
                 RecyclableArrayBufferWriter<byte> writer = RecyclableArrayBufferWriter<byte>.Create(MaximumPayloadBytes);
                 var cache = Unsafe.As<IBufferDistributedCache>(_backendCache!); // type-checked already
+
                 var pendingBuffers = cache.TryGetAsync(key, writer, token);
                 if (!pendingBuffers.IsCompletedSuccessfully)
                 {
@@ -49,7 +54,7 @@ internal ValueTask<BufferChunk> GetFromL2Async(string key, CancellationToken tok
                 return new(result);
         }
 
-        return default;
+        return default; // treat as a "miss"
 
         static async Task<BufferChunk> AwaitedLegacyAsync(Task<byte[]?> pending, DefaultHybridCache @this)
         {
@@ -115,6 +120,11 @@ internal void SetL1<T>(string key, CacheItem<T> value, HybridCacheEntryOptions?
 
             // commit
             cacheEntry.Dispose();
+
+            if (HybridCacheEventSource.Log.IsEnabled())
+            {
+                HybridCacheEventSource.Log.LocalCacheWrite();
+            }
         }
     }
 

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

@@ -1,14 +1,18 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
+using System;
+using Microsoft.Extensions.Logging;
+
 namespace Microsoft.Extensions.Caching.Hybrid.Internal;
 
 internal partial class DefaultHybridCache
 {
     private sealed partial class MutableCacheItem<T> : CacheItem<T> // used to hold types that require defensive copies
     {
-        private IHybridCacheSerializer<T> _serializer = null!; // deferred until SetValue
+        private IHybridCacheSerializer<T>? _serializer;
         private BufferChunk _buffer;
+        private T? _fallbackValue; // only used in the case of serialization failures
 
         public override bool NeedsEvictionCallback => _buffer.ReturnToPool;
 
@@ -21,16 +25,27 @@ public void SetValue(ref BufferChunk buffer, IHybridCacheSerializer<T> serialize
             buffer = default; // we're taking over the lifetime; the caller no longer has it!
         }
 
-        public override bool TryGetValue(out T value)
+        public void SetFallbackValue(T fallbackValue)
+        {
+            _fallbackValue = fallbackValue;
+        }
+
+        public override bool TryGetValue(ILogger log, out T value)
         {
             // only if we haven't already burned
             if (TryReserve())
             {
                 try
                 {
-                    value = _serializer.Deserialize(_buffer.AsSequence());
+                    var serializer = _serializer;
+                    value = serializer is null ? _fallbackValue! : serializer.Deserialize(_buffer.AsSequence());
                     return true;
                 }
+                catch (Exception ex)
+                {
+                    log.DeserializationFailure(ex);
+                    throw;
+                }
                 finally
                 {
                     _ = Release();

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

@@ -3,7 +3,7 @@
 
 using System;
 using System.Collections.Concurrent;
-using System.Reflection;
+using System.Diagnostics.CodeAnalysis;
 using System.Runtime.CompilerServices;
 using Microsoft.Extensions.DependencyInjection;
 
@@ -51,4 +51,54 @@ static IHybridCacheSerializer<T> ResolveAndAddSerializer(DefaultHybridCache @thi
             return serializer;
         }
     }
+
+    [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "Intentional for logged failure mode")]
+    private bool TrySerialize<T>(T value, out BufferChunk buffer, out IHybridCacheSerializer<T>? serializer)
+    {
+        // note: also returns the serializer we resolved, because most-any time we want to serialize, we'll also want
+        // to make sure we use that same instance later (without needing to re-resolve and/or store the entire HC machinery)
+
+        RecyclableArrayBufferWriter<byte>? writer = null;
+        buffer = default;
+        try
+        {
+            writer = RecyclableArrayBufferWriter<byte>.Create(MaximumPayloadBytes); // note this lifetime spans the SetL2Async
+            serializer = GetSerializer<T>();
+
+            serializer.Serialize(value, writer);
+
+            buffer = new(writer.DetachCommitted(out var length), length, returnToPool: true); // remove buffer ownership from the writer
+            writer.Dispose(); // we're done with the writer
+            return true;
+        }
+        catch (Exception ex)
+        {
+            bool knownCause = false;
+
+            // ^^^ if we know what happened, we can record directly via cause-specific events
+            // and treat as a handled failure (i.e. return false) - otherwise, we'll bubble
+            // the fault up a few layers *in addition to* logging in a failure event
+
+            if (writer is not null)
+            {
+                if (writer.QuotaExceeded)
+                {
+                    _logger.MaximumPayloadBytesExceeded(ex, MaximumPayloadBytes);
+                    knownCause = true;
+                }
+
+                writer.Dispose();
+            }
+
+            if (!knownCause)
+            {
+                _logger.SerializationFailure(ex);
+                throw;
+            }
+
+            buffer = default;
+            serializer = null;
+            return false;
+        }
+    }
 }

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

@@ -74,8 +74,6 @@ protected StampedeState(DefaultHybridCache cache, in StampedeKey key, CacheItem
 
         public abstract void Execute();
 
-        protected int MaximumPayloadBytes => _cache.MaximumPayloadBytes;
-
         public override string ToString() => Key.ToString();
 
         public abstract void SetCanceled();