diff --git a/eng/packages/TestOnly.props b/eng/packages/TestOnly.props index f6753c9c14d..4c78b8dcbe8 100644 --- a/eng/packages/TestOnly.props +++ b/eng/packages/TestOnly.props @@ -7,6 +7,7 @@ + @@ -20,7 +21,7 @@ - + diff --git a/eng/spellchecking_exclusions.dic b/eng/spellchecking_exclusions.dic index 2fc9b74699b..72596816516 100644 Binary files a/eng/spellchecking_exclusions.dic and b/eng/spellchecking_exclusions.dic differ diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.CacheItem.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.CacheItem.cs index 5585b9b2a29..05edc65dc06 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.CacheItem.cs +++ b/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 : 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(); } diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.ImmutableCacheItem.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.ImmutableCacheItem.cs index 9ae8468ba29..2e803d87ad6 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.ImmutableCacheItem.cs +++ b/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 diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.L2.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.L2.cs index 1e694448737..230a657bdc3 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.L2.cs +++ b/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 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 GetFromL2Async(string key, CancellationToken tok case CacheFeatures.BackendCache | CacheFeatures.BackendBuffers: // IBufferWriter-based RecyclableArrayBufferWriter writer = RecyclableArrayBufferWriter.Create(MaximumPayloadBytes); var cache = Unsafe.As(_backendCache!); // type-checked already + var pendingBuffers = cache.TryGetAsync(key, writer, token); if (!pendingBuffers.IsCompletedSuccessfully) { @@ -49,7 +54,7 @@ internal ValueTask GetFromL2Async(string key, CancellationToken tok return new(result); } - return default; + return default; // treat as a "miss" static async Task AwaitedLegacyAsync(Task pending, DefaultHybridCache @this) { @@ -115,6 +120,11 @@ internal void SetL1(string key, CacheItem value, HybridCacheEntryOptions? // commit cacheEntry.Dispose(); + + if (HybridCacheEventSource.Log.IsEnabled()) + { + HybridCacheEventSource.Log.LocalCacheWrite(); + } } } diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.MutableCacheItem.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.MutableCacheItem.cs index 2d02c23b6d8..db95e8c4590 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.MutableCacheItem.cs +++ b/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 : CacheItem // used to hold types that require defensive copies { - private IHybridCacheSerializer _serializer = null!; // deferred until SetValue + private IHybridCacheSerializer? _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 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(); diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.Serialization.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.Serialization.cs index 523a95e279a..d12b2cce592 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.Serialization.cs +++ b/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 ResolveAndAddSerializer(DefaultHybridCache @thi return serializer; } } + + [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "Intentional for logged failure mode")] + private bool TrySerialize(T value, out BufferChunk buffer, out IHybridCacheSerializer? 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? writer = null; + buffer = default; + try + { + writer = RecyclableArrayBufferWriter.Create(MaximumPayloadBytes); // note this lifetime spans the SetL2Async + serializer = GetSerializer(); + + 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; + } + } } diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.StampedeState.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.StampedeState.cs index eba71774395..e2439357f26 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.StampedeState.cs +++ b/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(); diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.StampedeStateT.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.StampedeStateT.cs index 4e45acae930..4be5b351485 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.StampedeStateT.cs +++ b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.StampedeStateT.cs @@ -6,6 +6,7 @@ using System.Diagnostics.CodeAnalysis; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using static Microsoft.Extensions.Caching.Hybrid.Internal.DefaultHybridCache; namespace Microsoft.Extensions.Caching.Hybrid.Internal; @@ -14,7 +15,8 @@ internal partial class DefaultHybridCache { internal sealed class StampedeState : StampedeState { - private const HybridCacheEntryFlags FlagsDisableL1AndL2 = HybridCacheEntryFlags.DisableLocalCacheWrite | HybridCacheEntryFlags.DisableDistributedCacheWrite; + // note on terminology: L1 and L2 are, for brevity, used interchangeably with "local" and "distributed" cache, i.e. `IMemoryCache` and `IDistributedCache` + private const HybridCacheEntryFlags FlagsDisableL1AndL2Write = HybridCacheEntryFlags.DisableLocalCacheWrite | HybridCacheEntryFlags.DisableDistributedCacheWrite; private readonly TaskCompletionSource>? _result; private TState? _state; @@ -76,13 +78,13 @@ public Task ExecuteDirectAsync(in TState state, Func _result?.TrySetCanceled(SharedToken); [SuppressMessage("Usage", "VSTHRD003:Avoid awaiting foreign Tasks", Justification = "Custom task management")] - public ValueTask JoinAsync(CancellationToken token) + public ValueTask JoinAsync(ILogger log, CancellationToken token) { // If the underlying has already completed, and/or our local token can't cancel: we // can simply wrap the shared task; otherwise, we need our own cancellation state. - return token.CanBeCanceled && !Task.IsCompleted ? WithCancellationAsync(this, token) : UnwrapReservedAsync(); + return token.CanBeCanceled && !Task.IsCompleted ? WithCancellationAsync(log, this, token) : UnwrapReservedAsync(log); - static async ValueTask WithCancellationAsync(StampedeState stampede, CancellationToken token) + static async ValueTask WithCancellationAsync(ILogger log, StampedeState stampede, CancellationToken token) { var cancelStub = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); using var reg = token.Register(static obj => @@ -112,7 +114,7 @@ static async ValueTask WithCancellationAsync(StampedeState stamped } // outside the catch, so we know we only decrement one way or the other - return result.GetReservedValue(); + return result.GetReservedValue(log); } } @@ -133,7 +135,7 @@ static Task> InvalidAsync() => System.Threading.Tasks.Task.FromExce [SuppressMessage("Performance", "CA1849:Call async methods when in an async method", Justification = "Checked manual unwrap")] [SuppressMessage("Usage", "VSTHRD003:Avoid awaiting foreign Tasks", Justification = "Checked manual unwrap")] [SuppressMessage("Major Code Smell", "S1121:Assignments should not be made from within sub-expressions", Justification = "Unusual, but legit here")] - internal ValueTask UnwrapReservedAsync() + internal ValueTask UnwrapReservedAsync(ILogger log) { var task = Task; #if NETCOREAPP2_0_OR_GREATER || NETSTANDARD2_1_OR_GREATER @@ -142,16 +144,16 @@ internal ValueTask UnwrapReservedAsync() if (task.Status == TaskStatus.RanToCompletion) #endif { - return new(task.Result.GetReservedValue()); + return new(task.Result.GetReservedValue(log)); } // if the type is immutable, callers can share the final step too (this may leave dangling // reservation counters, but that's OK) - var result = ImmutableTypeCache.IsImmutable ? (_sharedUnwrap ??= AwaitedAsync(Task)) : AwaitedAsync(Task); + var result = ImmutableTypeCache.IsImmutable ? (_sharedUnwrap ??= AwaitedAsync(log, Task)) : AwaitedAsync(log, Task); return new(result); - static async Task AwaitedAsync(Task> task) - => (await task.ConfigureAwait(false)).GetReservedValue(); + static async Task AwaitedAsync(ILogger log, Task> task) + => (await task.ConfigureAwait(false)).GetReservedValue(log); } [DoesNotReturn] @@ -161,12 +163,43 @@ static async Task AwaitedAsync(Task> task) [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "Exception is passed through to faulted task result")] private async Task BackgroundFetchAsync() { + bool eventSourceEnabled = HybridCacheEventSource.Log.IsEnabled(); try { // read from L2 if appropriate if ((Key.Flags & HybridCacheEntryFlags.DisableDistributedCacheRead) == 0) { - var result = await Cache.GetFromL2Async(Key.Key, SharedToken).ConfigureAwait(false); + BufferChunk result; + try + { + if (eventSourceEnabled) + { + HybridCacheEventSource.Log.DistributedCacheGet(); + } + + result = await Cache.GetFromL2Async(Key.Key, SharedToken).ConfigureAwait(false); + if (eventSourceEnabled) + { + if (result.Array is not null) + { + HybridCacheEventSource.Log.DistributedCacheHit(); + } + else + { + HybridCacheEventSource.Log.DistributedCacheMiss(); + } + } + } + catch (Exception ex) + { + if (eventSourceEnabled) + { + HybridCacheEventSource.Log.DistributedCacheFailed(); + } + + Cache._logger.CacheUnderlyingDataQueryFailure(ex); + result = default; // treat as "miss" + } if (result.Array is not null) { @@ -179,7 +212,30 @@ private async Task BackgroundFetchAsync() if ((Key.Flags & HybridCacheEntryFlags.DisableUnderlyingData) == 0) { // invoke the callback supplied by the caller - T newValue = await _underlying!(_state!, SharedToken).ConfigureAwait(false); + T newValue; + try + { + if (eventSourceEnabled) + { + HybridCacheEventSource.Log.UnderlyingDataQueryStart(); + } + + newValue = await _underlying!(_state!, SharedToken).ConfigureAwait(false); + + if (eventSourceEnabled) + { + HybridCacheEventSource.Log.UnderlyingDataQueryComplete(); + } + } + catch + { + if (eventSourceEnabled) + { + HybridCacheEventSource.Log.UnderlyingDataQueryFailed(); + } + + throw; + } // If we're writing this value *anywhere*, we're going to need to serialize; this is obvious // in the case of L2, but we also need it for L1, because MemoryCache might be enforcing @@ -187,11 +243,11 @@ private async Task BackgroundFetchAsync() // Likewise, if we're writing to a MutableCacheItem, we'll be serializing *anyway* for the payload. // // Rephrasing that: the only scenario in which we *do not* need to serialize is if: - // - it is an ImmutableCacheItem - // - we're writing neither to L1 nor L2 + // - it is an ImmutableCacheItem (so we don't need bytes for the CacheItem, L1) + // - we're not writing to L2 CacheItem cacheItem = CacheItem; - bool skipSerialize = cacheItem is ImmutableCacheItem && (Key.Flags & FlagsDisableL1AndL2) == FlagsDisableL1AndL2; + bool skipSerialize = cacheItem is ImmutableCacheItem && (Key.Flags & FlagsDisableL1AndL2Write) == FlagsDisableL1AndL2Write; if (skipSerialize) { @@ -202,33 +258,55 @@ private async Task BackgroundFetchAsync() // ^^^ The first thing we need to do is make sure we're not getting into a thread race over buffer disposal. // In particular, if this cache item is somehow so short-lived that the buffers would be released *before* we're // done writing them to L2, which happens *after* we've provided the value to consumers. - RecyclableArrayBufferWriter writer = RecyclableArrayBufferWriter.Create(MaximumPayloadBytes); // note this lifetime spans the SetL2Async - IHybridCacheSerializer serializer = Cache.GetSerializer(); - serializer.Serialize(newValue, writer); - BufferChunk buffer = new(writer.DetachCommitted(out var length), length, returnToPool: true); // remove buffer ownership from the writer - writer.Dispose(); // we're done with the writer - - // protect "buffer" (this is why we "reserved") for writing to L2 if needed; SetResultPreSerialized - // *may* (depending on context) claim this buffer, in which case "bufferToRelease" gets reset, and - // the final RecycleIfAppropriate() is a no-op; however, the buffer is valid in either event, - // (with TryReserve above guaranteeing that we aren't in a race condition). - BufferChunk bufferToRelease = buffer; - - // and since "bufferToRelease" is the thing that will be returned at some point, we can make it explicit - // that we do not need or want "buffer" to do any recycling (they're the same memory) - buffer = buffer.DoNotReturnToPool(); - - // set the underlying result for this operation (includes L1 write if appropriate) - SetResultPreSerialized(newValue, ref bufferToRelease, serializer); - - // Note that at this point we've already released most or all of the waiting callers. Everything - // from this point onwards happens in the background, from the perspective of the calling code. - - // Write to L2 if appropriate. - if ((Key.Flags & HybridCacheEntryFlags.DisableDistributedCacheWrite) == 0) + + BufferChunk bufferToRelease = default; + if (Cache.TrySerialize(newValue, out var buffer, out var serializer)) { - // We already have the payload serialized, so this is trivial to do. - await Cache.SetL2Async(Key.Key, in buffer, _options, SharedToken).ConfigureAwait(false); + // note we also capture the resolved serializer ^^^ - we'll need it again later + + // protect "buffer" (this is why we "reserved") for writing to L2 if needed; SetResultPreSerialized + // *may* (depending on context) claim this buffer, in which case "bufferToRelease" gets reset, and + // the final RecycleIfAppropriate() is a no-op; however, the buffer is valid in either event, + // (with TryReserve above guaranteeing that we aren't in a race condition). + bufferToRelease = buffer; + + // and since "bufferToRelease" is the thing that will be returned at some point, we can make it explicit + // that we do not need or want "buffer" to do any recycling (they're the same memory) + buffer = buffer.DoNotReturnToPool(); + + // set the underlying result for this operation (includes L1 write if appropriate) + SetResultPreSerialized(newValue, ref bufferToRelease, serializer); + + // Note that at this point we've already released most or all of the waiting callers. Everything + // from this point onwards happens in the background, from the perspective of the calling code. + + // Write to L2 if appropriate. + if ((Key.Flags & HybridCacheEntryFlags.DisableDistributedCacheWrite) == 0) + { + // We already have the payload serialized, so this is trivial to do. + try + { + await Cache.SetL2Async(Key.Key, in buffer, _options, SharedToken).ConfigureAwait(false); + + if (eventSourceEnabled) + { + HybridCacheEventSource.Log.DistributedCacheWrite(); + } + } + catch (Exception ex) + { + // log the L2 write failure, but that doesn't need to interrupt the app flow (so: + // don't rethrow); L1 will still reduce impact, and L1 without L2 is better than + // hard failure every time + Cache._logger.CacheBackendWriteFailure(ex); + } + } + } + else + { + // unable to serialize (or quota exceeded); try to at least store the onwards value; this is + // especially useful for immutable data types + SetResultPreSerialized(newValue, ref bufferToRelease, serializer); } // Release our hook on the CacheItem (only really important for "mutable"). @@ -309,7 +387,7 @@ private void SetResultAndRecycleIfAppropriate(ref BufferChunk value) private void SetImmutableResultWithoutSerialize(T value) { - Debug.Assert((Key.Flags & FlagsDisableL1AndL2) == FlagsDisableL1AndL2, "Only expected if L1+L2 disabled"); + Debug.Assert((Key.Flags & FlagsDisableL1AndL2Write) == FlagsDisableL1AndL2Write, "Only expected if L1+L2 disabled"); // set a result from a value we calculated directly CacheItem cacheItem; @@ -328,7 +406,7 @@ private void SetImmutableResultWithoutSerialize(T value) SetResult(cacheItem); } - private void SetResultPreSerialized(T value, ref BufferChunk buffer, IHybridCacheSerializer serializer) + private void SetResultPreSerialized(T value, ref BufferChunk buffer, IHybridCacheSerializer? serializer) { // set a result from a value we calculated directly that // has ALREADY BEEN SERIALIZED (we can optionally consume this buffer) @@ -343,8 +421,17 @@ private void SetResultPreSerialized(T value, ref BufferChunk buffer, IHybridCach // (but leave the buffer alone) break; case MutableCacheItem mutable: - mutable.SetValue(ref buffer, serializer); - mutable.DebugOnlyTrackBuffer(Cache); + if (serializer is null) + { + // serialization is failing; set fallback value + mutable.SetFallbackValue(value); + } + else + { + mutable.SetValue(ref buffer, serializer); + mutable.DebugOnlyTrackBuffer(Cache); + } + cacheItem = mutable; break; default: diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.cs index c789e7c6652..71dbf71fd54 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.cs +++ b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/DefaultHybridCache.cs @@ -22,6 +22,9 @@ namespace Microsoft.Extensions.Caching.Hybrid.Internal; /// internal sealed partial class DefaultHybridCache : HybridCache { + // reserve non-printable characters from keys, to prevent potential L2 abuse + private static readonly char[] _keyReservedCharacters = Enumerable.Range(0, 32).Select(i => (char)i).ToArray(); + [System.Diagnostics.CodeAnalysis.SuppressMessage("Style", "IDE0032:Use auto property", Justification = "Keep usage explicit")] private readonly IDistributedCache? _backendCache; [System.Diagnostics.CodeAnalysis.SuppressMessage("Style", "IDE0032:Use auto property", Justification = "Keep usage explicit")] @@ -37,6 +40,7 @@ internal sealed partial class DefaultHybridCache : HybridCache private readonly HybridCacheEntryFlags _defaultFlags; // note this already includes hardFlags private readonly TimeSpan _defaultExpiration; private readonly TimeSpan _defaultLocalCacheExpiration; + private readonly int _maximumKeyLength; private readonly DistributedCacheEntryOptions _defaultDistributedCacheExpiration; @@ -90,6 +94,7 @@ public DefaultHybridCache(IOptions options, IServiceProvider _serializerFactories = factories; MaximumPayloadBytes = checked((int)_options.MaximumPayloadBytes); // for now hard-limit to 2GiB + _maximumKeyLength = _options.MaximumKeyLength; var defaultEntryOptions = _options.DefaultEntryOptions; @@ -119,11 +124,33 @@ public override ValueTask GetOrCreateAsync(string key, TState stat } var flags = GetEffectiveFlags(options); - if ((flags & HybridCacheEntryFlags.DisableLocalCacheRead) == 0 && _localCache.TryGetValue(key, out var untyped) - && untyped is CacheItem typed && typed.TryGetValue(out var value)) + if (!ValidateKey(key)) { - // short-circuit - return new(value); + // we can't use cache, but we can still provide the data + return RunWithoutCacheAsync(flags, state, underlyingDataCallback, cancellationToken); + } + + bool eventSourceEnabled = HybridCacheEventSource.Log.IsEnabled(); + if ((flags & HybridCacheEntryFlags.DisableLocalCacheRead) == 0) + { + if (_localCache.TryGetValue(key, out var untyped) + && untyped is CacheItem typed && typed.TryGetValue(_logger, out var value)) + { + // short-circuit + if (eventSourceEnabled) + { + HybridCacheEventSource.Log.LocalCacheHit(); + } + + return new(value); + } + else + { + if (eventSourceEnabled) + { + HybridCacheEventSource.Log.LocalCacheMiss(); + } + } } if (GetOrCreateStampedeState(key, flags, out var stampede, canBeCanceled)) @@ -139,11 +166,19 @@ public override ValueTask GetOrCreateAsync(string key, TState stat { // we're going to run to completion; no need to get complicated _ = stampede.ExecuteDirectAsync(in state, underlyingDataCallback, options); // this larger task includes L2 write etc - return stampede.UnwrapReservedAsync(); + return stampede.UnwrapReservedAsync(_logger); + } + } + else + { + // pre-existing query + if (eventSourceEnabled) + { + HybridCacheEventSource.Log.StampedeJoin(); } } - return stampede.JoinAsync(cancellationToken); + return stampede.JoinAsync(_logger, cancellationToken); } public override ValueTask RemoveAsync(string key, CancellationToken token = default) @@ -164,7 +199,39 @@ public override ValueTask SetAsync(string key, T value, HybridCacheEntryOptio return new(state.ExecuteDirectAsync(value, static (state, _) => new(state), options)); // note this spans L2 write etc } + private static ValueTask RunWithoutCacheAsync(HybridCacheEntryFlags flags, TState state, + Func> underlyingDataCallback, + CancellationToken cancellationToken) + { + return (flags & HybridCacheEntryFlags.DisableUnderlyingData) == 0 + ? underlyingDataCallback(state, cancellationToken) : default; + } + [MethodImpl(MethodImplOptions.AggressiveInlining)] private HybridCacheEntryFlags GetEffectiveFlags(HybridCacheEntryOptions? options) - => (options?.Flags | _hardFlags) ?? _defaultFlags; + => (options?.Flags | _hardFlags) ?? _defaultFlags; + + private bool ValidateKey(string key) + { + if (string.IsNullOrWhiteSpace(key)) + { + _logger.KeyEmptyOrWhitespace(); + return false; + } + + if (key.Length > _maximumKeyLength) + { + _logger.MaximumKeyLengthExceeded(_maximumKeyLength, key.Length); + return false; + } + + if (key.IndexOfAny(_keyReservedCharacters) >= 0) + { + _logger.KeyInvalidContent(); + return false; + } + + // nothing to complain about + return true; + } } diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/HybridCacheEventSource.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/HybridCacheEventSource.cs new file mode 100644 index 00000000000..92a5d729e57 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/HybridCacheEventSource.cs @@ -0,0 +1,203 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Runtime.CompilerServices; +using System.Threading; + +namespace Microsoft.Extensions.Caching.Hybrid.Internal; + +[EventSource(Name = "Microsoft-Extensions-HybridCache")] +internal sealed class HybridCacheEventSource : EventSource +{ + public static readonly HybridCacheEventSource Log = new(); + + internal const int EventIdLocalCacheHit = 1; + internal const int EventIdLocalCacheMiss = 2; + internal const int EventIdDistributedCacheGet = 3; + internal const int EventIdDistributedCacheHit = 4; + internal const int EventIdDistributedCacheMiss = 5; + internal const int EventIdDistributedCacheFailed = 6; + internal const int EventIdUnderlyingDataQueryStart = 7; + internal const int EventIdUnderlyingDataQueryComplete = 8; + internal const int EventIdUnderlyingDataQueryFailed = 9; + internal const int EventIdLocalCacheWrite = 10; + internal const int EventIdDistributedCacheWrite = 11; + internal const int EventIdStampedeJoin = 12; + + // fast local counters + private long _totalLocalCacheHit; + private long _totalLocalCacheMiss; + private long _totalDistributedCacheHit; + private long _totalDistributedCacheMiss; + private long _totalUnderlyingDataQuery; + private long _currentUnderlyingDataQuery; + private long _currentDistributedFetch; + private long _totalLocalCacheWrite; + private long _totalDistributedCacheWrite; + private long _totalStampedeJoin; + +#if !(NETSTANDARD2_0 || NET462) + // full Counter infrastructure + private DiagnosticCounter[]? _counters; +#endif + + [NonEvent] + public void ResetCounters() + { + Debug.WriteLine($"{nameof(HybridCacheEventSource)} counters reset!"); + + Volatile.Write(ref _totalLocalCacheHit, 0); + Volatile.Write(ref _totalLocalCacheMiss, 0); + Volatile.Write(ref _totalDistributedCacheHit, 0); + Volatile.Write(ref _totalDistributedCacheMiss, 0); + Volatile.Write(ref _totalUnderlyingDataQuery, 0); + Volatile.Write(ref _currentUnderlyingDataQuery, 0); + Volatile.Write(ref _currentDistributedFetch, 0); + Volatile.Write(ref _totalLocalCacheWrite, 0); + Volatile.Write(ref _totalDistributedCacheWrite, 0); + Volatile.Write(ref _totalStampedeJoin, 0); + } + + [Event(EventIdLocalCacheHit, Level = EventLevel.Verbose)] + public void LocalCacheHit() + { + DebugAssertEnabled(); + _ = Interlocked.Increment(ref _totalLocalCacheHit); + WriteEvent(EventIdLocalCacheHit); + } + + [Event(EventIdLocalCacheMiss, Level = EventLevel.Verbose)] + public void LocalCacheMiss() + { + DebugAssertEnabled(); + _ = Interlocked.Increment(ref _totalLocalCacheMiss); + WriteEvent(EventIdLocalCacheMiss); + } + + [Event(EventIdDistributedCacheGet, Level = EventLevel.Verbose)] + public void DistributedCacheGet() + { + // should be followed by DistributedCacheHit, DistributedCacheMiss or DistributedCacheFailed + DebugAssertEnabled(); + _ = Interlocked.Increment(ref _currentDistributedFetch); + WriteEvent(EventIdDistributedCacheGet); + } + + [Event(EventIdDistributedCacheHit, Level = EventLevel.Verbose)] + public void DistributedCacheHit() + { + DebugAssertEnabled(); + + // note: not concerned about off-by-one here, i.e. don't panic + // about these two being atomic ref each-other - just the overall shape + _ = Interlocked.Increment(ref _totalDistributedCacheHit); + _ = Interlocked.Decrement(ref _currentDistributedFetch); + WriteEvent(EventIdDistributedCacheHit); + } + + [Event(EventIdDistributedCacheMiss, Level = EventLevel.Verbose)] + public void DistributedCacheMiss() + { + DebugAssertEnabled(); + + // note: not concerned about off-by-one here, i.e. don't panic + // about these two being atomic ref each-other - just the overall shape + _ = Interlocked.Increment(ref _totalDistributedCacheMiss); + _ = Interlocked.Decrement(ref _currentDistributedFetch); + WriteEvent(EventIdDistributedCacheMiss); + } + + [Event(EventIdDistributedCacheFailed, Level = EventLevel.Error)] + public void DistributedCacheFailed() + { + DebugAssertEnabled(); + _ = Interlocked.Decrement(ref _currentDistributedFetch); + WriteEvent(EventIdDistributedCacheFailed); + } + + [Event(EventIdUnderlyingDataQueryStart, Level = EventLevel.Verbose)] + public void UnderlyingDataQueryStart() + { + // should be followed by UnderlyingDataQueryComplete or UnderlyingDataQueryFailed + DebugAssertEnabled(); + _ = Interlocked.Increment(ref _totalUnderlyingDataQuery); + _ = Interlocked.Increment(ref _currentUnderlyingDataQuery); + WriteEvent(EventIdUnderlyingDataQueryStart); + } + + [Event(EventIdUnderlyingDataQueryComplete, Level = EventLevel.Verbose)] + public void UnderlyingDataQueryComplete() + { + DebugAssertEnabled(); + _ = Interlocked.Decrement(ref _currentUnderlyingDataQuery); + WriteEvent(EventIdUnderlyingDataQueryComplete); + } + + [Event(EventIdUnderlyingDataQueryFailed, Level = EventLevel.Error)] + public void UnderlyingDataQueryFailed() + { + DebugAssertEnabled(); + _ = Interlocked.Decrement(ref _currentUnderlyingDataQuery); + WriteEvent(EventIdUnderlyingDataQueryFailed); + } + + [Event(EventIdLocalCacheWrite, Level = EventLevel.Verbose)] + public void LocalCacheWrite() + { + DebugAssertEnabled(); + _ = Interlocked.Increment(ref _totalLocalCacheWrite); + WriteEvent(EventIdLocalCacheWrite); + } + + [Event(EventIdDistributedCacheWrite, Level = EventLevel.Verbose)] + public void DistributedCacheWrite() + { + DebugAssertEnabled(); + _ = Interlocked.Increment(ref _totalDistributedCacheWrite); + WriteEvent(EventIdDistributedCacheWrite); + } + + [Event(EventIdStampedeJoin, Level = EventLevel.Verbose)] + internal void StampedeJoin() + { + DebugAssertEnabled(); + _ = Interlocked.Increment(ref _totalStampedeJoin); + WriteEvent(EventIdStampedeJoin); + } + +#if !(NETSTANDARD2_0 || NET462) + [System.Diagnostics.CodeAnalysis.SuppressMessage("Reliability", "CA2000:Dispose objects before losing scope", Justification = "Lifetime exceeds obvious scope; handed to event source")] + [NonEvent] + protected override void OnEventCommand(EventCommandEventArgs command) + { + if (command.Command == EventCommand.Enable) + { + // lazily create counters on first Enable + _counters ??= [ + new PollingCounter("total-local-cache-hits", this, () => Volatile.Read(ref _totalLocalCacheHit)) { DisplayName = "Total Local Cache Hits" }, + new PollingCounter("total-local-cache-misses", this, () => Volatile.Read(ref _totalLocalCacheMiss)) { DisplayName = "Total Local Cache Misses" }, + new PollingCounter("total-distributed-cache-hits", this, () => Volatile.Read(ref _totalDistributedCacheHit)) { DisplayName = "Total Distributed Cache Hits" }, + new PollingCounter("total-distributed-cache-misses", this, () => Volatile.Read(ref _totalDistributedCacheMiss)) { DisplayName = "Total Distributed Cache Misses" }, + new PollingCounter("total-data-query", this, () => Volatile.Read(ref _totalUnderlyingDataQuery)) { DisplayName = "Total Data Queries" }, + new PollingCounter("current-data-query", this, () => Volatile.Read(ref _currentUnderlyingDataQuery)) { DisplayName = "Current Data Queries" }, + new PollingCounter("current-distributed-cache-fetches", this, () => Volatile.Read(ref _currentDistributedFetch)) { DisplayName = "Current Distributed Cache Fetches" }, + new PollingCounter("total-local-cache-writes", this, () => Volatile.Read(ref _totalLocalCacheWrite)) { DisplayName = "Total Local Cache Writes" }, + new PollingCounter("total-distributed-cache-writes", this, () => Volatile.Read(ref _totalDistributedCacheWrite)) { DisplayName = "Total Distributed Cache Writes" }, + new PollingCounter("total-stampede-joins", this, () => Volatile.Read(ref _totalStampedeJoin)) { DisplayName = "Total Stampede Joins" }, + ]; + } + + base.OnEventCommand(command); + } +#endif + + [NonEvent] + [Conditional("DEBUG")] + private void DebugAssertEnabled([CallerMemberName] string caller = "") + { + Debug.Assert(IsEnabled(), $"Missing check to {nameof(HybridCacheEventSource)}.{nameof(Log)}.{nameof(IsEnabled)} from {caller}"); + Debug.WriteLine($"{nameof(HybridCacheEventSource)}: {caller}"); // also log all event calls, for visibility + } +} diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/InbuiltTypeSerializer.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/InbuiltTypeSerializer.cs index 3ef26341433..4800428a88f 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/InbuiltTypeSerializer.cs +++ b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/InbuiltTypeSerializer.cs @@ -17,6 +17,18 @@ internal sealed class InbuiltTypeSerializer : IHybridCacheSerializer, IH public static InbuiltTypeSerializer Instance { get; } = new(); string IHybridCacheSerializer.Deserialize(ReadOnlySequence source) + => DeserializeString(source); + + void IHybridCacheSerializer.Serialize(string value, IBufferWriter target) + => SerializeString(value, target); + + byte[] IHybridCacheSerializer.Deserialize(ReadOnlySequence source) + => source.ToArray(); + + void IHybridCacheSerializer.Serialize(byte[] value, IBufferWriter target) + => target.Write(value); + + internal static string DeserializeString(ReadOnlySequence source) { #if NET5_0_OR_GREATER return Encoding.UTF8.GetString(source); @@ -36,7 +48,7 @@ string IHybridCacheSerializer.Deserialize(ReadOnlySequence source) #endif } - void IHybridCacheSerializer.Serialize(string value, IBufferWriter target) + internal static void SerializeString(string value, IBufferWriter target) { #if NET5_0_OR_GREATER Encoding.UTF8.GetBytes(value, target); @@ -49,10 +61,4 @@ void IHybridCacheSerializer.Serialize(string value, IBufferWriter ArrayPool.Shared.Return(oversized); #endif } - - byte[] IHybridCacheSerializer.Deserialize(ReadOnlySequence source) - => source.ToArray(); - - void IHybridCacheSerializer.Serialize(byte[] value, IBufferWriter target) - => target.Write(value); } diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/Log.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/Log.cs new file mode 100644 index 00000000000..785107c32ec --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/Log.cs @@ -0,0 +1,49 @@ +// 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 static partial class Log +{ + internal const int IdMaximumPayloadBytesExceeded = 1; + internal const int IdSerializationFailure = 2; + internal const int IdDeserializationFailure = 3; + internal const int IdKeyEmptyOrWhitespace = 4; + internal const int IdMaximumKeyLengthExceeded = 5; + internal const int IdCacheBackendReadFailure = 6; + internal const int IdCacheBackendWriteFailure = 7; + internal const int IdKeyInvalidContent = 8; + + [LoggerMessage(LogLevel.Error, "Cache MaximumPayloadBytes ({Bytes}) exceeded.", EventName = "MaximumPayloadBytesExceeded", EventId = IdMaximumPayloadBytesExceeded, SkipEnabledCheck = false)] + internal static partial void MaximumPayloadBytesExceeded(this ILogger logger, Exception e, int bytes); + + // note that serialization is critical enough that we perform hard failures in addition to logging; serialization + // failures are unlikely to be transient (i.e. connectivity); we would rather this shows up in QA, rather than + // being invisible and people *thinking* they're using cache, when actually they are not + + [LoggerMessage(LogLevel.Error, "Cache serialization failure.", EventName = "SerializationFailure", EventId = IdSerializationFailure, SkipEnabledCheck = false)] + internal static partial void SerializationFailure(this ILogger logger, Exception e); + + // (see same notes per SerializationFailure) + [LoggerMessage(LogLevel.Error, "Cache deserialization failure.", EventName = "DeserializationFailure", EventId = IdDeserializationFailure, SkipEnabledCheck = false)] + internal static partial void DeserializationFailure(this ILogger logger, Exception e); + + [LoggerMessage(LogLevel.Error, "Cache key empty or whitespace.", EventName = "KeyEmptyOrWhitespace", EventId = IdKeyEmptyOrWhitespace, SkipEnabledCheck = false)] + internal static partial void KeyEmptyOrWhitespace(this ILogger logger); + + [LoggerMessage(LogLevel.Error, "Cache key maximum length exceeded (maximum: {MaxLength}, actual: {KeyLength}).", EventName = "MaximumKeyLengthExceeded", + EventId = IdMaximumKeyLengthExceeded, SkipEnabledCheck = false)] + internal static partial void MaximumKeyLengthExceeded(this ILogger logger, int maxLength, int keyLength); + + [LoggerMessage(LogLevel.Error, "Cache backend read failure.", EventName = "CacheBackendReadFailure", EventId = IdCacheBackendReadFailure, SkipEnabledCheck = false)] + internal static partial void CacheUnderlyingDataQueryFailure(this ILogger logger, Exception ex); + + [LoggerMessage(LogLevel.Error, "Cache backend write failure.", EventName = "CacheBackendWriteFailure", EventId = IdCacheBackendWriteFailure, SkipEnabledCheck = false)] + internal static partial void CacheBackendWriteFailure(this ILogger logger, Exception ex); + + [LoggerMessage(LogLevel.Error, "Cache key contains invalid content.", EventName = "KeyInvalidContent", EventId = IdKeyInvalidContent, SkipEnabledCheck = false)] + internal static partial void KeyInvalidContent(this ILogger logger); // for PII etc reasons, we won't include the actual key +} diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/RecyclableArrayBufferWriter.cs b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/RecyclableArrayBufferWriter.cs index 2f2da2c7019..985d55c9f0e 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/RecyclableArrayBufferWriter.cs +++ b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Internal/RecyclableArrayBufferWriter.cs @@ -46,20 +46,20 @@ internal sealed class RecyclableArrayBufferWriter : IBufferWriter, IDispos public int CommittedBytes => _index; public int FreeCapacity => _buffer.Length - _index; + public bool QuotaExceeded { get; private set; } + private static RecyclableArrayBufferWriter? _spare; + public static RecyclableArrayBufferWriter Create(int maxLength) { var obj = Interlocked.Exchange(ref _spare, null) ?? new(); - Debug.Assert(obj._index == 0, "index should be zero initially"); - obj._maxLength = maxLength; + obj.Initialize(maxLength); return obj; } private RecyclableArrayBufferWriter() { _buffer = []; - _index = 0; - _maxLength = int.MaxValue; } public void Dispose() @@ -91,6 +91,7 @@ public void Advance(int count) if (_index + count > _maxLength) { + QuotaExceeded = true; ThrowQuota(); } @@ -199,4 +200,12 @@ private void CheckAndResizeBuffer(int sizeHint) static void ThrowOutOfMemoryException() => throw new InvalidOperationException("Unable to grow buffer as requested"); } + + private void Initialize(int maxLength) + { + // think .ctor, but with pooled object re-use + _index = 0; + _maxLength = maxLength; + QuotaExceeded = false; + } } diff --git a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Microsoft.Extensions.Caching.Hybrid.csproj b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Microsoft.Extensions.Caching.Hybrid.csproj index 1c59ccc088a..dfa70cd121e 100644 --- a/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Microsoft.Extensions.Caching.Hybrid.csproj +++ b/src/Libraries/Microsoft.Extensions.Caching.Hybrid/Microsoft.Extensions.Caching.Hybrid.csproj @@ -4,7 +4,7 @@ Multi-level caching implementation building on and extending IDistributedCache $(NetCoreTargetFrameworks)$(ConditionalNet462);netstandard2.0;netstandard2.1 true - cache;distributedcache;hybrid + cache;distributedcache;hybridcache true true true @@ -20,6 +20,11 @@ true + true + true + + + false diff --git a/src/Libraries/Microsoft.Extensions.Compliance.Abstractions/Microsoft.Extensions.Compliance.Abstractions.csproj b/src/Libraries/Microsoft.Extensions.Compliance.Abstractions/Microsoft.Extensions.Compliance.Abstractions.csproj index 5a6c93e1dc7..c83b7284da5 100644 --- a/src/Libraries/Microsoft.Extensions.Compliance.Abstractions/Microsoft.Extensions.Compliance.Abstractions.csproj +++ b/src/Libraries/Microsoft.Extensions.Compliance.Abstractions/Microsoft.Extensions.Compliance.Abstractions.csproj @@ -1,6 +1,7 @@  Microsoft.Extensions.Compliance + $(NetCoreTargetFrameworks);netstandard2.0; Abstractions to help ensure compliant data management. Fundamentals diff --git a/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/HybridCacheEventSourceTests.cs b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/HybridCacheEventSourceTests.cs new file mode 100644 index 00000000000..3a266af7ce3 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/HybridCacheEventSourceTests.cs @@ -0,0 +1,205 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Diagnostics.Tracing; +using Microsoft.Extensions.Caching.Hybrid.Internal; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Caching.Hybrid.Tests; + +public class HybridCacheEventSourceTests(ITestOutputHelper log, TestEventListener listener) : IClassFixture +{ + // see notes in TestEventListener for context on fixture usage + + [SkippableFact] + public void MatchesNameAndGuid() + { + // Assert + Assert.Equal("Microsoft-Extensions-HybridCache", listener.Source.Name); + Assert.Equal(Guid.Parse("b3aca39e-5dc9-5e21-f669-b72225b66cfc"), listener.Source.Guid); // from name + } + + [SkippableFact] + public async Task LocalCacheHit() + { + AssertEnabled(); + + listener.Reset().Source.LocalCacheHit(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdLocalCacheHit, "LocalCacheHit", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("total-local-cache-hits", "Total Local Cache Hits", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task LocalCacheMiss() + { + AssertEnabled(); + + listener.Reset().Source.LocalCacheMiss(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdLocalCacheMiss, "LocalCacheMiss", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("total-local-cache-misses", "Total Local Cache Misses", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task DistributedCacheGet() + { + AssertEnabled(); + + listener.Reset().Source.DistributedCacheGet(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdDistributedCacheGet, "DistributedCacheGet", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("current-distributed-cache-fetches", "Current Distributed Cache Fetches", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task DistributedCacheHit() + { + AssertEnabled(); + + listener.Reset().Source.DistributedCacheGet(); + listener.Reset(resetCounters: false).Source.DistributedCacheHit(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdDistributedCacheHit, "DistributedCacheHit", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("total-distributed-cache-hits", "Total Distributed Cache Hits", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task DistributedCacheMiss() + { + AssertEnabled(); + + listener.Reset().Source.DistributedCacheGet(); + listener.Reset(resetCounters: false).Source.DistributedCacheMiss(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdDistributedCacheMiss, "DistributedCacheMiss", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("total-distributed-cache-misses", "Total Distributed Cache Misses", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task DistributedCacheFailed() + { + AssertEnabled(); + + listener.Reset().Source.DistributedCacheGet(); + listener.Reset(resetCounters: false).Source.DistributedCacheFailed(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdDistributedCacheFailed, "DistributedCacheFailed", EventLevel.Error); + + await AssertCountersAsync(); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task UnderlyingDataQueryStart() + { + AssertEnabled(); + + listener.Reset().Source.UnderlyingDataQueryStart(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdUnderlyingDataQueryStart, "UnderlyingDataQueryStart", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("current-data-query", "Current Data Queries", 1); + listener.AssertCounter("total-data-query", "Total Data Queries", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task UnderlyingDataQueryComplete() + { + AssertEnabled(); + + listener.Reset().Source.UnderlyingDataQueryStart(); + listener.Reset(resetCounters: false).Source.UnderlyingDataQueryComplete(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdUnderlyingDataQueryComplete, "UnderlyingDataQueryComplete", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("total-data-query", "Total Data Queries", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task UnderlyingDataQueryFailed() + { + AssertEnabled(); + + listener.Reset().Source.UnderlyingDataQueryStart(); + listener.Reset(resetCounters: false).Source.UnderlyingDataQueryFailed(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdUnderlyingDataQueryFailed, "UnderlyingDataQueryFailed", EventLevel.Error); + + await AssertCountersAsync(); + listener.AssertCounter("total-data-query", "Total Data Queries", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task LocalCacheWrite() + { + AssertEnabled(); + + listener.Reset().Source.LocalCacheWrite(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdLocalCacheWrite, "LocalCacheWrite", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("total-local-cache-writes", "Total Local Cache Writes", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task DistributedCacheWrite() + { + AssertEnabled(); + + listener.Reset().Source.DistributedCacheWrite(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdDistributedCacheWrite, "DistributedCacheWrite", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("total-distributed-cache-writes", "Total Distributed Cache Writes", 1); + listener.AssertRemainingCountersZero(); + } + + [SkippableFact] + public async Task StampedeJoin() + { + AssertEnabled(); + + listener.Reset().Source.StampedeJoin(); + listener.AssertSingleEvent(HybridCacheEventSource.EventIdStampedeJoin, "StampedeJoin", EventLevel.Verbose); + + await AssertCountersAsync(); + listener.AssertCounter("total-stampede-joins", "Total Stampede Joins", 1); + listener.AssertRemainingCountersZero(); + } + + private void AssertEnabled() + { + // including this data for visibility when tests fail - ETW subsystem can be ... weird + log.WriteLine($".NET {Environment.Version} on {Environment.OSVersion}, {IntPtr.Size * 8}-bit"); + + Skip.IfNot(listener.Source.IsEnabled(), "Event source not enabled"); + } + + private async Task AssertCountersAsync() + { + var count = await listener.TryAwaitCountersAsync(); + + // ETW counters timing can be painfully unpredictable; generally + // it'll work fine locally, especially on modern .NET, but: + // CI servers and netfx in particular - not so much. The tests + // can still observe and validate the simple events, though, which + // should be enough to be credible that the eventing system is + // fundamentally working. We're not meant to be testing that + // the counters system *itself* works! + + Skip.If(count == 0, "No counters received"); + } +} diff --git a/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/LogCollector.cs b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/LogCollector.cs new file mode 100644 index 00000000000..bdb5ff981c0 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/LogCollector.cs @@ -0,0 +1,84 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using Microsoft.Extensions.Logging; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Caching.Hybrid.Tests; + +// dummy implementation for collecting test output +internal class LogCollector : ILoggerProvider +{ + private readonly List<(string categoryName, LogLevel logLevel, EventId eventId, Exception? exception, string message)> _items = []; + + public (string categoryName, LogLevel logLevel, EventId eventId, Exception? exception, string message)[] ToArray() + { + lock (_items) + { + return _items.ToArray(); + } + } + + public void WriteTo(ITestOutputHelper log) + { + lock (_items) + { + foreach (var logItem in _items) + { + var errSuffix = logItem.exception is null ? "" : $" - {logItem.exception.Message}"; + log.WriteLine($"{logItem.categoryName} {logItem.eventId}: {logItem.message}{errSuffix}"); + } + } + } + + public void AssertErrors(int[] errorIds) + { + lock (_items) + { + bool same; + if (errorIds.Length == _items.Count) + { + int index = 0; + same = true; + foreach (var item in _items) + { + if (item.eventId.Id != errorIds[index++]) + { + same = false; + break; + } + } + } + else + { + same = false; + } + + if (!same) + { + // we expect this to fail, then + Assert.Equal(string.Join(",", errorIds), string.Join(",", _items.Select(static x => x.eventId.Id))); + } + } + } + + ILogger ILoggerProvider.CreateLogger(string categoryName) => new TypedLogCollector(this, categoryName); + + void IDisposable.Dispose() + { + // nothing to do + } + + private sealed class TypedLogCollector(LogCollector parent, string categoryName) : ILogger + { + IDisposable? ILogger.BeginScope(TState state) => null; + bool ILogger.IsEnabled(LogLevel logLevel) => true; + void ILogger.Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + { + lock (parent._items) + { + parent._items.Add((categoryName, logLevel, eventId, exception, formatter(state, exception))); + } + } + } +} diff --git a/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/Microsoft.Extensions.Caching.Hybrid.Tests.csproj b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/Microsoft.Extensions.Caching.Hybrid.Tests.csproj index ef80a84eee9..fb8863cf776 100644 --- a/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/Microsoft.Extensions.Caching.Hybrid.Tests.csproj +++ b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/Microsoft.Extensions.Caching.Hybrid.Tests.csproj @@ -12,13 +12,15 @@ + - + + diff --git a/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/NullDistributedCache.cs b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/NullDistributedCache.cs new file mode 100644 index 00000000000..d07cb51bb93 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/NullDistributedCache.cs @@ -0,0 +1,31 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using Microsoft.Extensions.Caching.Distributed; + +namespace Microsoft.Extensions.Caching.Hybrid.Tests; + +// dummy L2 that doesn't actually store anything +internal class NullDistributedCache : IDistributedCache +{ + byte[]? IDistributedCache.Get(string key) => null; + Task IDistributedCache.GetAsync(string key, CancellationToken token) => Task.FromResult(null); + void IDistributedCache.Refresh(string key) + { + // nothing to do + } + + Task IDistributedCache.RefreshAsync(string key, CancellationToken token) => Task.CompletedTask; + void IDistributedCache.Remove(string key) + { + // nothing to do + } + + Task IDistributedCache.RemoveAsync(string key, CancellationToken token) => Task.CompletedTask; + void IDistributedCache.Set(string key, byte[] value, DistributedCacheEntryOptions options) + { + // nothing to do + } + + Task IDistributedCache.SetAsync(string key, byte[] value, DistributedCacheEntryOptions options, CancellationToken token) => Task.CompletedTask; +} diff --git a/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/SizeTests.cs b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/SizeTests.cs index 119c2297882..66f4fc7628d 100644 --- a/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/SizeTests.cs +++ b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/SizeTests.cs @@ -1,31 +1,60 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System.Buffers; +using System.ComponentModel; +using Microsoft.Extensions.Caching.Distributed; using Microsoft.Extensions.Caching.Hybrid.Internal; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Xunit.Abstractions; namespace Microsoft.Extensions.Caching.Hybrid.Tests; -public class SizeTests +public class SizeTests(ITestOutputHelper log) { [Theory] - [InlineData(null, true)] // does not enforce size limits - [InlineData(8L, false)] // unreasonably small limit; chosen because our test string has length 12 - hence no expectation to find the second time - [InlineData(1024L, true)] // reasonable size limit - public async Task ValidateSizeLimit_Immutable(long? sizeLimit, bool expectFromL1) + [InlineData("abc", null, true, null, null)] // does not enforce size limits + [InlineData("", null, false, null, null, Log.IdKeyEmptyOrWhitespace, Log.IdKeyEmptyOrWhitespace)] // invalid key + [InlineData(" ", null, false, null, null, Log.IdKeyEmptyOrWhitespace, Log.IdKeyEmptyOrWhitespace)] // invalid key + [InlineData(null, null, false, null, null, Log.IdKeyEmptyOrWhitespace, Log.IdKeyEmptyOrWhitespace)] // invalid key + [InlineData("abc", 8L, false, null, null)] // unreasonably small limit; chosen because our test string has length 12 - hence no expectation to find the second time + [InlineData("abc", 1024L, true, null, null)] // reasonable size limit + [InlineData("abc", 1024L, true, 8L, null, Log.IdMaximumPayloadBytesExceeded)] // reasonable size limit, small HC quota + [InlineData("abc", null, false, null, 2, Log.IdMaximumKeyLengthExceeded, Log.IdMaximumKeyLengthExceeded)] // key limit exceeded + [InlineData("a\u0000c", null, false, null, null, Log.IdKeyInvalidContent, Log.IdKeyInvalidContent)] // invalid key + [InlineData("a\u001Fc", null, false, null, null, Log.IdKeyInvalidContent, Log.IdKeyInvalidContent)] // invalid key + [InlineData("a\u0020c", null, true, null, null)] // fine (this is just space) + public async Task ValidateSizeLimit_Immutable(string? key, long? sizeLimit, bool expectFromL1, long? maximumPayloadBytes, int? maximumKeyLength, + params int[] errorIds) { + using var collector = new LogCollector(); var services = new ServiceCollection(); services.AddMemoryCache(options => options.SizeLimit = sizeLimit); - services.AddHybridCache(); + services.AddHybridCache(options => + { + if (maximumKeyLength.HasValue) + { + options.MaximumKeyLength = maximumKeyLength.GetValueOrDefault(); + } + + if (maximumPayloadBytes.HasValue) + { + options.MaximumPayloadBytes = maximumPayloadBytes.GetValueOrDefault(); + } + }); + services.AddLogging(options => + { + options.ClearProviders(); + options.AddProvider(collector); + }); using ServiceProvider provider = services.BuildServiceProvider(); var cache = Assert.IsType(provider.GetRequiredService()); - const string Key = "abc"; - // this looks weird; it is intentionally not a const - we want to check // same instance without worrying about interning from raw literals string expected = new("simple value".ToArray()); - var actual = await cache.GetOrCreateAsync(Key, ct => new(expected)); + var actual = await cache.GetOrCreateAsync(key!, ct => new(expected)); // expect same contents Assert.Equal(expected, actual); @@ -35,7 +64,7 @@ public async Task ValidateSizeLimit_Immutable(long? sizeLimit, bool expectFromL1 Assert.Same(expected, actual); // rinse and repeat, to check we get the value from L1 - actual = await cache.GetOrCreateAsync(Key, ct => new(Guid.NewGuid().ToString())); + actual = await cache.GetOrCreateAsync(key!, ct => new(Guid.NewGuid().ToString())); if (expectFromL1) { @@ -51,30 +80,54 @@ public async Task ValidateSizeLimit_Immutable(long? sizeLimit, bool expectFromL1 // L1 cache not used Assert.NotEqual(expected, actual); } + + collector.WriteTo(log); + collector.AssertErrors(errorIds); } [Theory] - [InlineData(null, true)] // does not enforce size limits - [InlineData(8L, false)] // unreasonably small limit; chosen because our test string has length 12 - hence no expectation to find the second time - [InlineData(1024L, true)] // reasonable size limit - public async Task ValidateSizeLimit_Mutable(long? sizeLimit, bool expectFromL1) + [InlineData("abc", null, true, null, null)] // does not enforce size limits + [InlineData("", null, false, null, null, Log.IdKeyEmptyOrWhitespace, Log.IdKeyEmptyOrWhitespace)] // invalid key + [InlineData(" ", null, false, null, null, Log.IdKeyEmptyOrWhitespace, Log.IdKeyEmptyOrWhitespace)] // invalid key + [InlineData(null, null, false, null, null, Log.IdKeyEmptyOrWhitespace, Log.IdKeyEmptyOrWhitespace)] // invalid key + [InlineData("abc", 8L, false, null, null)] // unreasonably small limit; chosen because our test string has length 12 - hence no expectation to find the second time + [InlineData("abc", 1024L, true, null, null)] // reasonable size limit + [InlineData("abc", 1024L, true, 8L, null, Log.IdMaximumPayloadBytesExceeded)] // reasonable size limit, small HC quota + [InlineData("abc", null, false, null, 2, Log.IdMaximumKeyLengthExceeded, Log.IdMaximumKeyLengthExceeded)] // key limit exceeded + public async Task ValidateSizeLimit_Mutable(string? key, long? sizeLimit, bool expectFromL1, long? maximumPayloadBytes, int? maximumKeyLength, + params int[] errorIds) { + using var collector = new LogCollector(); var services = new ServiceCollection(); services.AddMemoryCache(options => options.SizeLimit = sizeLimit); - services.AddHybridCache(); + services.AddHybridCache(options => + { + if (maximumKeyLength.HasValue) + { + options.MaximumKeyLength = maximumKeyLength.GetValueOrDefault(); + } + + if (maximumPayloadBytes.HasValue) + { + options.MaximumPayloadBytes = maximumPayloadBytes.GetValueOrDefault(); + } + }); + services.AddLogging(options => + { + options.ClearProviders(); + options.AddProvider(collector); + }); using ServiceProvider provider = services.BuildServiceProvider(); var cache = Assert.IsType(provider.GetRequiredService()); - const string Key = "abc"; - string expected = "simple value"; - var actual = await cache.GetOrCreateAsync(Key, ct => new(new MutablePoco { Value = expected })); + var actual = await cache.GetOrCreateAsync(key!, ct => new(new MutablePoco { Value = expected })); // expect same contents Assert.Equal(expected, actual.Value); // rinse and repeat, to check we get the value from L1 - actual = await cache.GetOrCreateAsync(Key, ct => new(new MutablePoco { Value = Guid.NewGuid().ToString() })); + actual = await cache.GetOrCreateAsync(key!, ct => new(new MutablePoco { Value = Guid.NewGuid().ToString() })); if (expectFromL1) { @@ -86,10 +139,217 @@ public async Task ValidateSizeLimit_Mutable(long? sizeLimit, bool expectFromL1) // L1 cache not used Assert.NotEqual(expected, actual.Value); } + + collector.WriteTo(log); + collector.AssertErrors(errorIds); + } + + [Theory] + [InlineData("some value", false, 1, 1, 2, false)] + [InlineData("read fail", false, 1, 1, 1, true, Log.IdDeserializationFailure)] + [InlineData("write fail", true, 1, 1, 0, true, Log.IdSerializationFailure)] + public async Task BrokenSerializer_Mutable(string value, bool same, int runCount, int serializeCount, int deserializeCount, bool expectKnownFailure, params int[] errorIds) + { + using var collector = new LogCollector(); + var services = new ServiceCollection(); + services.AddMemoryCache(); + services.AddSingleton(); + var serializer = new MutablePoco.Serializer(); + services.AddHybridCache().AddSerializer(serializer); + services.AddLogging(options => + { + options.ClearProviders(); + options.AddProvider(collector); + }); + using ServiceProvider provider = services.BuildServiceProvider(); + var cache = Assert.IsType(provider.GetRequiredService()); + + int actualRunCount = 0; + Func> func = _ => + { + Interlocked.Increment(ref actualRunCount); + return new(new MutablePoco { Value = value }); + }; + + if (expectKnownFailure) + { + await Assert.ThrowsAsync(async () => await cache.GetOrCreateAsync("key", func)); + } + else + { + var first = await cache.GetOrCreateAsync("key", func); + var second = await cache.GetOrCreateAsync("key", func); + Assert.Equal(value, first.Value); + Assert.Equal(value, second.Value); + + if (same) + { + Assert.Same(first, second); + } + else + { + Assert.NotSame(first, second); + } + } + + Assert.Equal(runCount, Volatile.Read(ref actualRunCount)); + Assert.Equal(serializeCount, serializer.WriteCount); + Assert.Equal(deserializeCount, serializer.ReadCount); + collector.WriteTo(log); + collector.AssertErrors(errorIds); + } + + [Theory] + [InlineData("some value", true, 1, 1, 0, false, true)] + [InlineData("read fail", true, 1, 1, 0, false, true)] + [InlineData("write fail", true, 1, 1, 0, true, true, Log.IdSerializationFailure)] + + // without L2, we only need the serializer for sizing purposes (L1), not used for deserialize + [InlineData("some value", true, 1, 1, 0, false, false)] + [InlineData("read fail", true, 1, 1, 0, false, false)] + [InlineData("write fail", true, 1, 1, 0, true, false, Log.IdSerializationFailure)] + [System.Diagnostics.CodeAnalysis.SuppressMessage("Major Code Smell", "S107:Methods should not have too many parameters", Justification = "Test scenario range; reducing duplication")] + public async Task BrokenSerializer_Immutable(string value, bool same, int runCount, int serializeCount, int deserializeCount, bool expectKnownFailure, bool withL2, + params int[] errorIds) + { + using var collector = new LogCollector(); + var services = new ServiceCollection(); + services.AddMemoryCache(); + if (withL2) + { + services.AddSingleton(); + } + + var serializer = new ImmutablePoco.Serializer(); + services.AddHybridCache().AddSerializer(serializer); + services.AddLogging(options => + { + options.ClearProviders(); + options.AddProvider(collector); + }); + using ServiceProvider provider = services.BuildServiceProvider(); + var cache = Assert.IsType(provider.GetRequiredService()); + + int actualRunCount = 0; + Func> func = _ => + { + Interlocked.Increment(ref actualRunCount); + return new(new ImmutablePoco(value)); + }; + + if (expectKnownFailure) + { + await Assert.ThrowsAsync(async () => await cache.GetOrCreateAsync("key", func)); + } + else + { + var first = await cache.GetOrCreateAsync("key", func); + var second = await cache.GetOrCreateAsync("key", func); + Assert.Equal(value, first.Value); + Assert.Equal(value, second.Value); + + if (same) + { + Assert.Same(first, second); + } + else + { + Assert.NotSame(first, second); + } + } + + Assert.Equal(runCount, Volatile.Read(ref actualRunCount)); + Assert.Equal(serializeCount, serializer.WriteCount); + Assert.Equal(deserializeCount, serializer.ReadCount); + collector.WriteTo(log); + collector.AssertErrors(errorIds); + } + + public class KnownFailureException : Exception + { + public KnownFailureException(string message) + : base(message) + { + } } public class MutablePoco { public string Value { get; set; } = ""; + + public sealed class Serializer : IHybridCacheSerializer + { + private int _readCount; + private int _writeCount; + + public int ReadCount => Volatile.Read(ref _readCount); + public int WriteCount => Volatile.Read(ref _writeCount); + + public MutablePoco Deserialize(ReadOnlySequence source) + { + Interlocked.Increment(ref _readCount); + var value = InbuiltTypeSerializer.DeserializeString(source); + if (value == "read fail") + { + throw new KnownFailureException("read failure"); + } + + return new MutablePoco { Value = value }; + } + + public void Serialize(MutablePoco value, IBufferWriter target) + { + Interlocked.Increment(ref _writeCount); + if (value.Value == "write fail") + { + throw new KnownFailureException("write failure"); + } + + InbuiltTypeSerializer.SerializeString(value.Value, target); + } + } + } + + [ImmutableObject(true)] + public sealed class ImmutablePoco + { + public ImmutablePoco(string value) + { + Value = value; + } + + public string Value { get; } + + public sealed class Serializer : IHybridCacheSerializer + { + private int _readCount; + private int _writeCount; + + public int ReadCount => Volatile.Read(ref _readCount); + public int WriteCount => Volatile.Read(ref _writeCount); + + public ImmutablePoco Deserialize(ReadOnlySequence source) + { + Interlocked.Increment(ref _readCount); + var value = InbuiltTypeSerializer.DeserializeString(source); + if (value == "read fail") + { + throw new KnownFailureException("read failure"); + } + + return new ImmutablePoco(value); + } + + public void Serialize(ImmutablePoco value, IBufferWriter target) + { + Interlocked.Increment(ref _writeCount); + if (value.Value == "write fail") + { + throw new KnownFailureException("write failure"); + } + + InbuiltTypeSerializer.SerializeString(value.Value, target); + } + } } } diff --git a/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/TestEventListener.cs b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/TestEventListener.cs new file mode 100644 index 00000000000..ecb97ef3c7e --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/TestEventListener.cs @@ -0,0 +1,189 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Globalization; +using Microsoft.Extensions.Caching.Hybrid.Internal; + +namespace Microsoft.Extensions.Caching.Hybrid.Tests; + +public sealed class TestEventListener : EventListener +{ + // captures both event and counter data + + // this is used as a class fixture from HybridCacheEventSourceTests, because there + // seems to be some unpredictable behaviours if multiple event sources/listeners are + // casually created etc + private const double EventCounterIntervalSec = 0.25; + + private readonly List<(int id, string name, EventLevel level)> _events = []; + private readonly Dictionary _counters = []; + + private object SyncLock => _events; + + internal HybridCacheEventSource Source { get; } = new(); + + public TestEventListener Reset(bool resetCounters = true) + { + lock (SyncLock) + { + _events.Clear(); + _counters.Clear(); + + if (resetCounters) + { + Source.ResetCounters(); + } + } + + Assert.True(Source.IsEnabled(), "should report as enabled"); + + return this; + } + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (ReferenceEquals(eventSource, Source)) + { + var args = new Dictionary + { + ["EventCounterIntervalSec"] = EventCounterIntervalSec.ToString("G", CultureInfo.InvariantCulture), + }; + EnableEvents(Source, EventLevel.Verbose, EventKeywords.All, args); + } + + base.OnEventSourceCreated(eventSource); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (ReferenceEquals(eventData.EventSource, Source)) + { + // capture counters/events + lock (SyncLock) + { + if (eventData.EventName == "EventCounters" + && eventData.Payload is { Count: > 0 }) + { + foreach (var payload in eventData.Payload) + { + if (payload is IDictionary map) + { + string? name = null; + string? displayName = null; + double? value = null; + bool isIncrement = false; + foreach (var pair in map) + { + switch (pair.Key) + { + case "Name" when pair.Value is string: + name = (string)pair.Value; + break; + case "DisplayName" when pair.Value is string s: + displayName = s; + break; + case "Mean": + isIncrement = false; + value = Convert.ToDouble(pair.Value); + break; + case "Increment": + isIncrement = true; + value = Convert.ToDouble(pair.Value); + break; + } + } + + if (name is not null && value is not null) + { + if (isIncrement && _counters.TryGetValue(name, out var oldPair)) + { + value += oldPair.value; // treat as delta from old + } + + Debug.WriteLine($"{name}={value}"); + _counters[name] = (displayName, value.Value); + } + } + } + } + else + { + _events.Add((eventData.EventId, eventData.EventName ?? "", eventData.Level)); + } + } + } + + base.OnEventWritten(eventData); + } + + public (int id, string name, EventLevel level) SingleEvent() + { + (int id, string name, EventLevel level) evt; + lock (SyncLock) + { + evt = Assert.Single(_events); + } + + return evt; + } + + public void AssertSingleEvent(int id, string name, EventLevel level) + { + var evt = SingleEvent(); + Assert.Equal(name, evt.name); + Assert.Equal(id, evt.id); + Assert.Equal(level, evt.level); + } + + public double AssertCounter(string name, string displayName) + { + lock (SyncLock) + { + Assert.True(_counters.TryGetValue(name, out var pair), $"counter not found: {name}"); + Assert.Equal(displayName, pair.displayName); + + _counters.Remove(name); // count as validated + return pair.value; + } + } + + public void AssertCounter(string name, string displayName, double expected) + { + var actual = AssertCounter(name, displayName); + if (!Equals(expected, actual)) + { + Assert.Fail($"{name}: expected {expected}, actual {actual}"); + } + } + + [System.Diagnostics.CodeAnalysis.SuppressMessage("Major Bug", "S1244:Floating point numbers should not be tested for equality", Justification = "Test expects exact zero")] + public void AssertRemainingCountersZero() + { + lock (SyncLock) + { + foreach (var pair in _counters) + { + if (pair.Value.value != 0) + { + Assert.Fail($"{pair.Key}: expected 0, actual {pair.Value.value}"); + } + } + } + } + + [System.Diagnostics.CodeAnalysis.SuppressMessage("Performance", "CA1822:Mark members as static", Justification = "Clarity and usability")] + public async Task TryAwaitCountersAsync() + { + // allow 2 cycles because if we only allow 1, we run the risk of a + // snapshot being captured mid-cycle when we were setting up the test + // (ok, that's an unlikely race condition, but!) + await Task.Delay(TimeSpan.FromSeconds(EventCounterIntervalSec * 2)); + + lock (SyncLock) + { + return _counters.Count; + } + } +} diff --git a/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/UnreliableL2Tests.cs b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/UnreliableL2Tests.cs new file mode 100644 index 00000000000..7af85f9cba2 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Caching.Hybrid.Tests/UnreliableL2Tests.cs @@ -0,0 +1,251 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Diagnostics.CodeAnalysis; +using Microsoft.Extensions.Caching.Distributed; +using Microsoft.Extensions.Caching.Hybrid.Internal; +using Microsoft.Extensions.Caching.Memory; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Caching.Hybrid.Tests; + +// validate HC stability when the L2 is unreliable +public class UnreliableL2Tests(ITestOutputHelper testLog) +{ + [Theory] + [InlineData(BreakType.None)] + [InlineData(BreakType.Synchronous, Log.IdCacheBackendWriteFailure)] + [InlineData(BreakType.Asynchronous, Log.IdCacheBackendWriteFailure)] + [InlineData(BreakType.AsynchronousYield, Log.IdCacheBackendWriteFailure)] + [SuppressMessage("Usage", "VSTHRD003:Avoid awaiting foreign Tasks", Justification = "Intentional; tracking for out-of-band support only")] + public async Task WriteFailureInvisible(BreakType writeBreak, params int[] errorIds) + { + using (GetServices(out var hc, out var l1, out var l2, out var log)) + using (log) + { + // normal behaviour when working fine + var x = await hc.GetOrCreateAsync("x", NewGuid); + Assert.Equal(x, await hc.GetOrCreateAsync("x", NewGuid)); + Assert.NotNull(l2.Tail.Get("x")); // exists + + l2.WriteBreak = writeBreak; + var y = await hc.GetOrCreateAsync("y", NewGuid); + Assert.Equal(y, await hc.GetOrCreateAsync("y", NewGuid)); + if (writeBreak == BreakType.None) + { + Assert.NotNull(l2.Tail.Get("y")); // exists + } + else + { + Assert.Null(l2.Tail.Get("y")); // does not exist + } + + await l2.LastWrite; // allows out-of-band write to complete + await Task.Delay(150); // even then: thread jitter can cause problems + + log.WriteTo(testLog); + log.AssertErrors(errorIds); + } + } + + [Theory] + [InlineData(BreakType.None)] + [InlineData(BreakType.Synchronous, Log.IdCacheBackendReadFailure, Log.IdCacheBackendReadFailure)] + [InlineData(BreakType.Asynchronous, Log.IdCacheBackendReadFailure, Log.IdCacheBackendReadFailure)] + [InlineData(BreakType.AsynchronousYield, Log.IdCacheBackendReadFailure, Log.IdCacheBackendReadFailure)] + public async Task ReadFailureInvisible(BreakType readBreak, params int[] errorIds) + { + using (GetServices(out var hc, out var l1, out var l2, out var log)) + using (log) + { + // create two new values via HC; this should go down to l2 + var x = await hc.GetOrCreateAsync("x", NewGuid); + var y = await hc.GetOrCreateAsync("y", NewGuid); + + // this should be reliable and repeatable + Assert.Equal(x, await hc.GetOrCreateAsync("x", NewGuid)); + Assert.Equal(y, await hc.GetOrCreateAsync("y", NewGuid)); + + // even if we clean L1, causing new L2 fetches + l1.Clear(); + Assert.Equal(x, await hc.GetOrCreateAsync("x", NewGuid)); + Assert.Equal(y, await hc.GetOrCreateAsync("y", NewGuid)); + + // now we break L2 in some predictable way, *without* clearing L1 - the + // values should still be available via L1 + l2.ReadBreak = readBreak; + Assert.Equal(x, await hc.GetOrCreateAsync("x", NewGuid)); + Assert.Equal(y, await hc.GetOrCreateAsync("y", NewGuid)); + + // but if we clear L1 to force L2 hits, we anticipate problems + l1.Clear(); + if (readBreak == BreakType.None) + { + Assert.Equal(x, await hc.GetOrCreateAsync("x", NewGuid)); + Assert.Equal(y, await hc.GetOrCreateAsync("y", NewGuid)); + } + else + { + // because L2 is unavailable and L1 is empty, we expect the callback + // to be used again, generating new values + var a = await hc.GetOrCreateAsync("x", NewGuid, NoL2Write); + var b = await hc.GetOrCreateAsync("y", NewGuid, NoL2Write); + + Assert.NotEqual(x, a); + Assert.NotEqual(y, b); + + // but those *new* values are at least reliable inside L1 + Assert.Equal(a, await hc.GetOrCreateAsync("x", NewGuid)); + Assert.Equal(b, await hc.GetOrCreateAsync("y", NewGuid)); + } + + log.WriteTo(testLog); + log.AssertErrors(errorIds); + } + } + + private static HybridCacheEntryOptions NoL2Write { get; } = new HybridCacheEntryOptions { Flags = HybridCacheEntryFlags.DisableDistributedCacheWrite }; + + public enum BreakType + { + None, // async API works correctly + Synchronous, // async API faults directly rather than return a faulted task + Asynchronous, // async API returns a completed asynchronous fault + AsynchronousYield, // async API returns an incomplete asynchronous fault + } + + private static ValueTask NewGuid(CancellationToken cancellationToken) => new(Guid.NewGuid()); + + private static IDisposable GetServices(out HybridCache hc, out MemoryCache l1, + out UnreliableDistributedCache l2, out LogCollector log) + { + // we need an entirely separate MC for the dummy backend, not connected to our + // "real" services + var services = new ServiceCollection(); + services.AddDistributedMemoryCache(); + var backend = services.BuildServiceProvider().GetRequiredService(); + + // now create the "real" services + l2 = new UnreliableDistributedCache(backend); + var collector = new LogCollector(); + log = collector; + services = new ServiceCollection(); + services.AddSingleton(l2); + services.AddHybridCache(); + services.AddLogging(options => + { + options.ClearProviders(); + options.AddProvider(collector); + }); + var lifetime = services.BuildServiceProvider(); + hc = lifetime.GetRequiredService(); + l1 = Assert.IsType(lifetime.GetRequiredService()); + return lifetime; + } + + private sealed class UnreliableDistributedCache : IDistributedCache + { + public UnreliableDistributedCache(IDistributedCache tail) + { + Tail = tail; + } + + public IDistributedCache Tail { get; } + public BreakType ReadBreak { get; set; } + public BreakType WriteBreak { get; set; } + + public Task LastWrite { get; private set; } = Task.CompletedTask; + + public byte[]? Get(string key) => throw new NotSupportedException(); // only async API in use + + public Task GetAsync(string key, CancellationToken token = default) + => TrackLast(ThrowIfBrokenAsync(ReadBreak) ?? Tail.GetAsync(key, token)); + + public void Refresh(string key) => throw new NotSupportedException(); // only async API in use + + public Task RefreshAsync(string key, CancellationToken token = default) + => TrackLast(ThrowIfBrokenAsync(WriteBreak) ?? Tail.RefreshAsync(key, token)); + + public void Remove(string key) => throw new NotSupportedException(); // only async API in use + + public Task RemoveAsync(string key, CancellationToken token = default) + => TrackLast(ThrowIfBrokenAsync(WriteBreak) ?? Tail.RemoveAsync(key, token)); + + public void Set(string key, byte[] value, DistributedCacheEntryOptions options) => throw new NotSupportedException(); // only async API in use + + public Task SetAsync(string key, byte[] value, DistributedCacheEntryOptions options, CancellationToken token = default) + => TrackLast(ThrowIfBrokenAsync(WriteBreak) ?? Tail.SetAsync(key, value, options, token)); + + [DoesNotReturn] + private static void Throw() => throw new IOException("L2 offline"); + + private static async Task ThrowAsync(bool yield) + { + if (yield) + { + await Task.Yield(); + } + + Throw(); + return default; // never reached + } + + private static Task? ThrowIfBrokenAsync(BreakType breakType) => ThrowIfBrokenAsync(breakType); + + [SuppressMessage("Critical Bug", "S4586:Non-async \"Task/Task\" methods should not return null", Justification = "Intentional for propagation")] + private static Task? ThrowIfBrokenAsync(BreakType breakType) + { + switch (breakType) + { + case BreakType.Asynchronous: + return ThrowAsync(false); + case BreakType.AsynchronousYield: + return ThrowAsync(true); + case BreakType.None: + return null; + default: + // includes BreakType.Synchronous and anything unknown + Throw(); + break; + } + + return null; + } + + [SuppressMessage("Usage", "VSTHRD003:Avoid awaiting foreign Tasks", Justification = "Intentional; tracking for out-of-band support only")] + [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "We don't need the failure type - just the timing")] + private static Task IgnoreFailure(Task task) + { + return task.Status == TaskStatus.RanToCompletion + ? Task.CompletedTask : IgnoreAsync(task); + + static async Task IgnoreAsync(Task task) + { + try + { + await task; + } + catch + { + // we only care about the "when"; failure is fine + } + } + } + + [SuppressMessage("Usage", "VSTHRD003:Avoid awaiting foreign Tasks", Justification = "Intentional; tracking for out-of-band support only")] + private Task TrackLast(Task lastWrite) + { + LastWrite = IgnoreFailure(lastWrite); + return lastWrite; + } + + [SuppressMessage("Usage", "VSTHRD003:Avoid awaiting foreign Tasks", Justification = "Intentional; tracking for out-of-band support only")] + private Task TrackLast(Task lastWrite) + { + LastWrite = IgnoreFailure(lastWrite); + return lastWrite; + } + } +} diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Abstractions.Tests/Microsoft.Extensions.Telemetry.Abstractions.Tests.csproj b/test/Libraries/Microsoft.Extensions.Telemetry.Abstractions.Tests/Microsoft.Extensions.Telemetry.Abstractions.Tests.csproj index ac284fee861..387cec3c5c0 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Abstractions.Tests/Microsoft.Extensions.Telemetry.Abstractions.Tests.csproj +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Abstractions.Tests/Microsoft.Extensions.Telemetry.Abstractions.Tests.csproj @@ -12,4 +12,8 @@ + + + +