From d6ebd2ca58a7121bb98d994cb61d47744a13422e Mon Sep 17 00:00:00 2001 From: VahidN Date: Tue, 10 Dec 2024 08:54:01 +0330 Subject: [PATCH] Add EFCacheKey to EFCacheableLogEvent --- .../DbCommandInterceptorProcessor.cs | 58 +++++++++---- .../EFCacheDependenciesProcessor.cs | 12 +-- .../EFCacheManagerCoreProvider.cs | 4 +- .../EFCachePolicyParser.cs | 10 ++- .../EFCacheableLogEvent.cs | 5 ++ .../EFCoreSecondLevelCacheInterceptor.csproj | 2 +- .../EFDebugLogger.cs | 8 +- .../EFEasyCachingCoreProvider.cs | 4 +- .../IEFDebugLogger.cs | 2 +- .../DbCommandInterceptorProcessorTests.cs | 42 +++++----- .../EFDebugLoggerTests.cs | 81 +++++++++++-------- 11 files changed, 144 insertions(+), 84 deletions(-) diff --git a/src/EFCoreSecondLevelCacheInterceptor/DbCommandInterceptorProcessor.cs b/src/EFCoreSecondLevelCacheInterceptor/DbCommandInterceptorProcessor.cs index c52c774..2b9d0c9 100644 --- a/src/EFCoreSecondLevelCacheInterceptor/DbCommandInterceptorProcessor.cs +++ b/src/EFCoreSecondLevelCacheInterceptor/DbCommandInterceptorProcessor.cs @@ -64,6 +64,8 @@ public T ProcessExecutedCommands(DbCommand command, DbContext? context, T res return result; } + EFCacheKey? efCacheKey = null; + try { if (!_cacheServiceCheck.IsCacheServiceAvailable()) @@ -84,14 +86,16 @@ public T ProcessExecutedCommands(DbCommand command, DbContext? context, T res { var logMessage = $"Returning the cached TableRows[{rowsReader.TableName}]."; _interceptorProcessorLogger.LogDebug(CacheableEventId.CacheHit, logMessage); - _logger.NotifyCacheableEvent(CacheableLogEventId.CacheHit, logMessage, command.CommandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.CacheHit, logMessage, command.CommandText, + efCacheKey); } return result; } var commandText = command.CommandText; - var efCacheKey = _cacheKeyProvider.GetEFCacheKey(command, context, cachePolicy ?? new EFCachePolicy()); + efCacheKey = _cacheKeyProvider.GetEFCacheKey(command, context, cachePolicy ?? new EFCachePolicy()); if (_cacheDependenciesProcessor.InvalidateCacheDependencies(commandText, efCacheKey)) { @@ -104,7 +108,7 @@ public T ProcessExecutedCommands(DbCommand command, DbContext? context, T res { var message = $"Skipping a none-cachable command[{commandText}]."; _interceptorProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText, efCacheKey); } return result; @@ -123,7 +127,9 @@ public T ProcessExecutedCommands(DbCommand command, DbContext? context, T res { var message = $"[{data}] added to the cache[{efCacheKey}]."; _interceptorProcessorLogger.LogDebug(CacheableEventId.QueryResultCached, message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultCached, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultCached, message, commandText, + efCacheKey); } } @@ -150,7 +156,9 @@ public T ProcessExecutedCommands(DbCommand command, DbContext? context, T res { var message = $"TableRows[{tableRows.TableName}] added to the cache[{efCacheKey}]."; _interceptorProcessorLogger.LogDebug(CacheableEventId.QueryResultCached, message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultCached, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultCached, message, commandText, + efCacheKey); } } @@ -174,7 +182,9 @@ public T ProcessExecutedCommands(DbCommand command, DbContext? context, T res { var message = $"[{result}] added to the cache[{efCacheKey}]."; _interceptorProcessorLogger.LogDebug(CacheableEventId.QueryResultCached, message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultCached, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultCached, message, commandText, + efCacheKey); } } @@ -193,7 +203,9 @@ public T ProcessExecutedCommands(DbCommand command, DbContext? context, T res if (_logger.IsLoggerEnabled) { _interceptorProcessorLogger.LogCritical(ex, message: "Interceptor Error"); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingError, ex.ToString(), command.CommandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingError, ex.ToString(), command.CommandText, + efCacheKey); } return result; @@ -210,6 +222,8 @@ public T ProcessExecutingCommands(DbCommand command, DbContext? context, T re return result; } + EFCacheKey? efCacheKey = null; + try { if (!_cacheServiceCheck.IsCacheServiceAvailable()) @@ -232,13 +246,13 @@ public T ProcessExecutingCommands(DbCommand command, DbContext? context, T re { var message = $"Skipping a none-cachable command[{commandText}]."; _interceptorProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText, efCacheKey); } return result; } - var efCacheKey = _cacheKeyProvider.GetEFCacheKey(command, context, cachePolicy); + efCacheKey = _cacheKeyProvider.GetEFCacheKey(command, context, cachePolicy); if (_cacheService.GetValue(efCacheKey, cachePolicy) is not { } cacheResult) { @@ -259,7 +273,9 @@ public T ProcessExecutingCommands(DbCommand command, DbContext? context, T re { var message = "Suppressed the result with an empty TableRows."; _interceptorProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, message, commandText, + efCacheKey); } using var rows = new EFTableRowsDataReader(new EFTableRows() @@ -278,7 +294,9 @@ public T ProcessExecutingCommands(DbCommand command, DbContext? context, T re $"Suppressed the result with the TableRows[{cacheResult.TableRows.TableName}] from the cache[{efCacheKey}]."; _interceptorProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, message, commandText, + efCacheKey); } using var dataRows = new EFTableRowsDataReader(cacheResult.TableRows @@ -299,7 +317,9 @@ public T ProcessExecutingCommands(DbCommand command, DbContext? context, T re { var message = $"Suppressed the result with {cachedResult} from the cache[{efCacheKey}]."; _interceptorProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, message, commandText, + efCacheKey); } return (T)Convert.ChangeType(InterceptionResult.SuppressWithResult(cachedResult), typeof(T), @@ -314,7 +334,9 @@ public T ProcessExecutingCommands(DbCommand command, DbContext? context, T re { var message = $"Suppressed the result with {cachedResult} from the cache[{efCacheKey}]."; _interceptorProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, message, commandText, + efCacheKey); } return (T)Convert.ChangeType( @@ -326,7 +348,7 @@ public T ProcessExecutingCommands(DbCommand command, DbContext? context, T re { var message = $"Skipped the result with {result?.GetType()} type."; _interceptorProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText, efCacheKey); } return result; @@ -341,7 +363,9 @@ public T ProcessExecutingCommands(DbCommand command, DbContext? context, T re if (_logger.IsLoggerEnabled) { _interceptorProcessorLogger.LogCritical(ex, message: "Interceptor Error"); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingError, ex.ToString(), command.CommandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingError, ex.ToString(), command.CommandText, + efCacheKey); } return result; @@ -396,7 +420,7 @@ private bool ShouldSkipCachingDbContext(DbContext context, string commandText) { var message = $"Skipped caching of this DbContext: {context.GetType()}"; _interceptorProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText, efCacheKey: null); } return result; @@ -421,7 +445,7 @@ private bool ShouldSkipCachingResults(string commandText, object value) { var message = "Skipped caching of this result based on the provided predicate."; _interceptorProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText, efCacheKey: null); } return result; diff --git a/src/EFCoreSecondLevelCacheInterceptor/EFCacheDependenciesProcessor.cs b/src/EFCoreSecondLevelCacheInterceptor/EFCacheDependenciesProcessor.cs index 38bb000..0dab6ba 100644 --- a/src/EFCoreSecondLevelCacheInterceptor/EFCacheDependenciesProcessor.cs +++ b/src/EFCoreSecondLevelCacheInterceptor/EFCacheDependenciesProcessor.cs @@ -95,7 +95,7 @@ public SortedSet GetCacheDependencies(EFCachePolicy cachePolicy, $"It's not possible to calculate the related table names of the current query[{commandText}]. Please use EFCachePolicy.Configure(options => options.CacheDependencies(\"real_table_name_1\", \"real_table_name_2\")) to specify them explicitly."; _dependenciesProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingError, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingError, message, commandText, efCacheKey: null); } cacheDependencies = new SortedSet(StringComparer.OrdinalIgnoreCase) @@ -125,7 +125,7 @@ public bool InvalidateCacheDependencies(string commandText, EFCacheKey cacheKey) { var message = $"Skipped invalidating a none-CRUD command[{commandText}]."; _dependenciesProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.InvalidationSkipped, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.InvalidationSkipped, message, commandText, cacheKey); } return false; @@ -139,7 +139,7 @@ public bool InvalidateCacheDependencies(string commandText, EFCacheKey cacheKey) $"Skipped invalidating the related cache entries of this query[{commandText}] based on the provided predicate."; _dependenciesProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.InvalidationSkipped, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.InvalidationSkipped, message, commandText, cacheKey); } return false; @@ -153,7 +153,7 @@ public bool InvalidateCacheDependencies(string commandText, EFCacheKey cacheKey) { var message = $"Invalidated [{string.Join(separator: ", ", cacheKey.CacheDependencies)}] dependencies."; _dependenciesProcessorLogger.LogDebug(CacheableEventId.QueryResultInvalidated, message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultInvalidated, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultInvalidated, message, commandText, cacheKey); } _logger.NotifyCacheInvalidation(clearAllCachedEntries: false, cacheKey.CacheDependencies); @@ -179,7 +179,9 @@ private void LogProcess(SortedSet tableNames, $"ContextTableNames: {names}, PossibleQueryTableNames: {texts} -> CacheDependencies: {dependencies}."; _dependenciesProcessorLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.CacheDependenciesCalculated, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.CacheDependenciesCalculated, message, commandText, + efCacheKey: null); } } diff --git a/src/EFCoreSecondLevelCacheInterceptor/EFCacheManagerCoreProvider.cs b/src/EFCoreSecondLevelCacheInterceptor/EFCacheManagerCoreProvider.cs index 1a6a3d8..0c2b9a6 100644 --- a/src/EFCoreSecondLevelCacheInterceptor/EFCacheManagerCoreProvider.cs +++ b/src/EFCoreSecondLevelCacheInterceptor/EFCacheManagerCoreProvider.cs @@ -143,7 +143,9 @@ public void InvalidateCacheDependencies(EFCacheKey cacheKey) $"Invalidated all of the cache entries due to early expiration of a root cache key[{rootCacheKey}]."; _cacheManagerCoreProviderLogger.LogDebug(CacheableEventId.QueryResultInvalidated, message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultInvalidated, message, commandText: ""); + + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultInvalidated, message, commandText: "", + cacheKey); } ClearAllCachedEntries(); diff --git a/src/EFCoreSecondLevelCacheInterceptor/EFCachePolicyParser.cs b/src/EFCoreSecondLevelCacheInterceptor/EFCachePolicyParser.cs index 0f0cdf4..04df778 100644 --- a/src/EFCoreSecondLevelCacheInterceptor/EFCachePolicyParser.cs +++ b/src/EFCoreSecondLevelCacheInterceptor/EFCachePolicyParser.cs @@ -131,7 +131,9 @@ public string RemoveEFCachePolicyTag(string commandText) { var message = $"Using EFCachePolicy: {efCachePolicy}."; _policyParserLogger.LogDebug(message: "Using EFCachePolicy: {EfCachePolicy}.", efCachePolicy); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachePolicyCalculated, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.CachePolicyCalculated, message, commandText, + efCacheKey: null); } return efCachePolicy; @@ -145,7 +147,7 @@ private bool ShouldSkipCachingCommands(string commandText) { var message = $"Skipped caching of this command[{commandText}] based on the provided predicate."; _policyParserLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText); + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText, efCacheKey: null); } return result; @@ -446,7 +448,9 @@ private bool ContainsNonDeterministicFunction(string commandText) { var message = $"Skipped caching because of the non-deterministic function -> `{item}`."; _policyParserLogger.LogDebug(message); - _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText); + + _logger.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, message, commandText, + efCacheKey: null); } return hasFn; diff --git a/src/EFCoreSecondLevelCacheInterceptor/EFCacheableLogEvent.cs b/src/EFCoreSecondLevelCacheInterceptor/EFCacheableLogEvent.cs index 3151deb..b6f88da 100644 --- a/src/EFCoreSecondLevelCacheInterceptor/EFCacheableLogEvent.cs +++ b/src/EFCoreSecondLevelCacheInterceptor/EFCacheableLogEvent.cs @@ -22,6 +22,11 @@ public class EFCacheableLogEvent /// public string CommandText { set; get; } = default!; + /// + /// Stores information of the computed key of the input LINQ query. + /// + public EFCacheKey? EFCacheKey { set; get; } + /// /// Defines a mechanism for retrieving a service object. /// For instance, you can create an ILoggerFactory by using it. diff --git a/src/EFCoreSecondLevelCacheInterceptor/EFCoreSecondLevelCacheInterceptor.csproj b/src/EFCoreSecondLevelCacheInterceptor/EFCoreSecondLevelCacheInterceptor.csproj index 95e074f..513c71e 100644 --- a/src/EFCoreSecondLevelCacheInterceptor/EFCoreSecondLevelCacheInterceptor.csproj +++ b/src/EFCoreSecondLevelCacheInterceptor/EFCoreSecondLevelCacheInterceptor.csproj @@ -1,7 +1,7 @@  Entity Framework Core Second Level Caching Library. - 4.8.8 + 4.9.0 Vahid Nasiri net9.0;net8.0;net7.0;net6.0;net5.0;netstandard2.1;netstandard2.0;net462;netcoreapp3.1; true diff --git a/src/EFCoreSecondLevelCacheInterceptor/EFDebugLogger.cs b/src/EFCoreSecondLevelCacheInterceptor/EFDebugLogger.cs index c7a528f..8d48cc2 100644 --- a/src/EFCoreSecondLevelCacheInterceptor/EFDebugLogger.cs +++ b/src/EFCoreSecondLevelCacheInterceptor/EFDebugLogger.cs @@ -42,7 +42,7 @@ public EFDebugLogger(IOptions cacheSettings, { var message = $"InstanceId: {Guid.NewGuid()}, Started @{DateTime.UtcNow} UTC."; logger.LogDebug(message); - NotifyCacheableEvent(CacheableLogEventId.CachingSystemStarted, message, commandText: ""); + NotifyCacheableEvent(CacheableLogEventId.CachingSystemStarted, message, commandText: "", efCacheKey: null); } } @@ -54,7 +54,10 @@ public EFDebugLogger(IOptions cacheSettings, /// /// If you set DisableLogging to false, this delegate will give you the internal caching events of the library. /// - public void NotifyCacheableEvent(CacheableLogEventId eventId, string message, string commandText) + public void NotifyCacheableEvent(CacheableLogEventId eventId, + string message, + string commandText, + EFCacheKey? efCacheKey) { if (IsLoggerEnabled && _cacheableEvent is not null) { @@ -63,6 +66,7 @@ public void NotifyCacheableEvent(CacheableLogEventId eventId, string message, st EventId = eventId, Message = message, CommandText = commandText, + EFCacheKey = efCacheKey, ServiceProvider = _serviceProvider }); } diff --git a/src/EFCoreSecondLevelCacheInterceptor/EFEasyCachingCoreProvider.cs b/src/EFCoreSecondLevelCacheInterceptor/EFEasyCachingCoreProvider.cs index 55dcdce..8569b04 100644 --- a/src/EFCoreSecondLevelCacheInterceptor/EFEasyCachingCoreProvider.cs +++ b/src/EFCoreSecondLevelCacheInterceptor/EFEasyCachingCoreProvider.cs @@ -158,7 +158,9 @@ public void InvalidateCacheDependencies(EFCacheKey cacheKey) $"Invalidated all of the cache entries due to early expiration of a root cache key[{rootCacheKey}]."; _easyCachingCoreProviderLogger.LogDebug(CacheableEventId.QueryResultInvalidated, message); - _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultInvalidated, message, commandText: ""); + + _logger.NotifyCacheableEvent(CacheableLogEventId.QueryResultInvalidated, message, commandText: "", + cacheKey); } ClearAllCachedEntries(); diff --git a/src/EFCoreSecondLevelCacheInterceptor/IEFDebugLogger.cs b/src/EFCoreSecondLevelCacheInterceptor/IEFDebugLogger.cs index 1859be9..094bdbb 100644 --- a/src/EFCoreSecondLevelCacheInterceptor/IEFDebugLogger.cs +++ b/src/EFCoreSecondLevelCacheInterceptor/IEFDebugLogger.cs @@ -15,7 +15,7 @@ public interface IEFDebugLogger /// /// If you set DisableLogging to false, this delegate will give you the internal caching events of the library. /// - void NotifyCacheableEvent(CacheableLogEventId eventId, string message, string commandText); + void NotifyCacheableEvent(CacheableLogEventId eventId, string message, string commandText, EFCacheKey? efCacheKey); /// /// Represents some information about the current cache invalidation event diff --git a/src/Tests/EFCoreSecondLevelCacheInterceptor.UnitTests/DbCommandInterceptorProcessorTests.cs b/src/Tests/EFCoreSecondLevelCacheInterceptor.UnitTests/DbCommandInterceptorProcessorTests.cs index 2c17c42..7343dd8 100644 --- a/src/Tests/EFCoreSecondLevelCacheInterceptor.UnitTests/DbCommandInterceptorProcessorTests.cs +++ b/src/Tests/EFCoreSecondLevelCacheInterceptor.UnitTests/DbCommandInterceptorProcessorTests.cs @@ -153,7 +153,7 @@ public void ProcessExecutedCommands_NotifiesCachingErrorEvent_WhenThrowsInvalidO It.Is(message => message.Contains( "System.InvalidOperationException: Operation is not valid due to the current state of the object.")), - null), Times.Once); + null, null), Times.Once); } [Fact] @@ -219,7 +219,7 @@ public void // Assert _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, - "Skipped caching of this DbContext: Castle.Proxies.DbContextProxy", string.Empty), Times.Once); + "Skipped caching of this DbContext: Castle.Proxies.DbContextProxy", string.Empty, null), Times.Once); } [Fact] @@ -338,7 +338,7 @@ public void ProcessExecutedCommands_NotifiesCachingSkippedEvent_WhenIsCrudComman // Assert _loggerMock.Verify( - x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, "Skipping a none-cachable command[].", + x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, "Skipping a none-cachable command[].", null, null), Times.Once); } @@ -397,7 +397,7 @@ public void ProcessExecutedCommands_NotifiesCacheHitEvent_WhenReturningCachedTab // Assert _loggerMock.Verify( - x => x.NotifyCacheableEvent(CacheableLogEventId.CacheHit, "Returning the cached TableRows[].", null), + x => x.NotifyCacheableEvent(CacheableLogEventId.CacheHit, "Returning the cached TableRows[].", null, null), Times.Once); } @@ -459,7 +459,7 @@ public void ProcessExecutedCommands_NotifiesCacheHitEvent_WhenSkipsCachingResult // Assert _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, - "Skipped caching of this result based on the provided predicate.", null), Times.Once); + "Skipped caching of this result based on the provided predicate.", null, null), Times.Once); } [Fact] @@ -518,7 +518,8 @@ public void ProcessExecutedCommands_NotifiesQueryResultCachedEvent_WhenIntDataAd // Assert _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.QueryResultCached, - "[2147483647] added to the cache[KeyHash: , DbContext: , CacheDependencies: .].", null), Times.Once); + "[2147483647] added to the cache[KeyHash: , DbContext: , CacheDependencies: .].", null, efCacheKey), + Times.Once); } [Fact] @@ -632,7 +633,7 @@ public void ProcessExecutedCommands_NotifiesCacheHitEvent_WhenSkipsCachingResult // Assert _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, - "Skipped caching of this result based on the provided predicate.", null), Times.Once); + "Skipped caching of this result based on the provided predicate.", null, null), Times.Once); } [Fact] @@ -690,8 +691,8 @@ public void ProcessExecutedCommands_NotifiesQueryResultCachedEvent_WhenEFTableRo _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.QueryResultCached, It.Is(message - => message.Contains(" added to the cache[KeyHash: , DbContext: , CacheDependencies: .].")), null), - Times.Once); + => message.Contains(" added to the cache[KeyHash: , DbContext: , CacheDependencies: .].")), null, + efCacheKey), Times.Once); } [Fact] @@ -750,7 +751,7 @@ public void ProcessExecutedCommands_NotifiesCacheHitEvent_WhenSkipsCachingResult // Assert _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, - "Skipped caching of this result based on the provided predicate.", null), Times.Once); + "Skipped caching of this result based on the provided predicate.", null, null), Times.Once); } [Fact] @@ -807,7 +808,8 @@ public void ProcessExecutedCommands_NotifiesQueryResultCachedEvent_WhenObjectDat // Assert _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.QueryResultCached, - "[System.Object] added to the cache[KeyHash: , DbContext: , CacheDependencies: .].", null), Times.Once); + "[System.Object] added to the cache[KeyHash: , DbContext: , CacheDependencies: .].", null, efCacheKey), + Times.Once); } [Fact] @@ -933,7 +935,7 @@ public void ProcessExecutingCommands_NotifiesCachingErrorEvent_WhenThrowsInvalid It.Is(message => message.Contains( "System.InvalidOperationException: Operation is not valid due to the current state of the object.")), - null), Times.Once); + null, null), Times.Once); } [Fact] @@ -999,7 +1001,7 @@ public void // Assert _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, - "Skipped caching of this DbContext: Castle.Proxies.DbContextProxy", string.Empty), Times.Once); + "Skipped caching of this DbContext: Castle.Proxies.DbContextProxy", string.Empty, null), Times.Once); } [Fact] @@ -1087,7 +1089,7 @@ public void ProcessExecutingCommands_NotifiesCachingSkippedEvent_WhenCachePolicy // Assert _loggerMock.Verify( - x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, "Skipping a none-cachable command[].", + x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, "Skipping a none-cachable command[].", null, null), Times.Once); } @@ -1140,7 +1142,7 @@ public void ProcessExecutingCommands_NotifiesQueryResultSuppressedEvent_WhenThro // Assert _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, - "Suppressed the result with an empty TableRows.", null), Times.Once); + "Suppressed the result with an empty TableRows.", null, efCacheKey), Times.Once); } [Fact] @@ -1203,7 +1205,7 @@ public void ProcessExecutingCommands_NotifiesQueryResultSuppressedEvent_WhenCach _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, "Suppressed the result with the TableRows[] from the cache[KeyHash: , DbContext: , CacheDependencies: .].", - null), Times.Once); + null, efCacheKey), Times.Once); } [Fact] @@ -1237,7 +1239,7 @@ public void ProcessExecutingCommands_NotifiesQueryResultSuppressedEvent_WhenInte _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, "Suppressed the result with 2147483647 from the cache[KeyHash: , DbContext: , CacheDependencies: .].", - null), Times.Once); + null, efCacheKey), Times.Once); } [Fact] @@ -1305,7 +1307,7 @@ public void ProcessExecutingCommands_NotifiesQueryResultSuppressedEvent_WhenInte _loggerMock.Verify( x => x.NotifyCacheableEvent(CacheableLogEventId.QueryResultSuppressed, "Suppressed the result with System.Object from the cache[KeyHash: , DbContext: , CacheDependencies: .].", - null), Times.Once); + null, efCacheKey), Times.Once); } [Fact] @@ -1366,8 +1368,8 @@ public void ProcessExecutingCommands_NotifiesCachingSkippedEvent_WhenResultIsNul // Assert _loggerMock.Verify( - x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, "Skipped the result with type.", null), - Times.Once); + x => x.NotifyCacheableEvent(CacheableLogEventId.CachingSkipped, "Skipped the result with type.", null, + efCacheKey), Times.Once); } [Fact] diff --git a/src/Tests/EFCoreSecondLevelCacheInterceptor.UnitTests/EFDebugLoggerTests.cs b/src/Tests/EFCoreSecondLevelCacheInterceptor.UnitTests/EFDebugLoggerTests.cs index 82e88f2..ac07950 100644 --- a/src/Tests/EFCoreSecondLevelCacheInterceptor.UnitTests/EFDebugLoggerTests.cs +++ b/src/Tests/EFCoreSecondLevelCacheInterceptor.UnitTests/EFDebugLoggerTests.cs @@ -9,8 +9,8 @@ public class EFDebugLoggerTests { private readonly Mock> _cacheableEventMock; private readonly Mock> _cacheInvalidationEventMock; - private readonly Mock _serviceProviderMock; private readonly IEFDebugLogger _debugLogger; + private readonly Mock _serviceProviderMock; public EFDebugLoggerTests() { @@ -20,6 +20,7 @@ public EFDebugLoggerTests() var cacheSettingsMock = new Mock>(); var loggerMock = new Mock>(); + var cacheSettings = new EFCoreSecondLevelCacheSettings { EnableLogging = true, @@ -28,12 +29,9 @@ public EFDebugLoggerTests() }; cacheSettingsMock.Setup(c => c.Value).Returns(cacheSettings); - loggerMock.Setup(l => l.IsEnabled(LogLevel.Debug)).Returns(true); + loggerMock.Setup(l => l.IsEnabled(LogLevel.Debug)).Returns(value: true); - _debugLogger = new EFDebugLogger( - cacheSettingsMock.Object, - loggerMock.Object, - _serviceProviderMock.Object); + _debugLogger = new EFDebugLogger(cacheSettingsMock.Object, loggerMock.Object, _serviceProviderMock.Object); } [Fact] @@ -43,8 +41,8 @@ public void EFDebugLogger_ThrowsArgumentNullException_WhenCacheSettingsIsNull() var loggerMock = new Mock>(); var serviceProviderMock = new Mock(); - Assert.Throws(() => - new EFDebugLogger(null!, loggerMock.Object, serviceProviderMock.Object)); + Assert.Throws(() + => new EFDebugLogger(null!, loggerMock.Object, serviceProviderMock.Object)); } [Fact] @@ -55,8 +53,8 @@ public void EFDebugLogger_ThrowsArgumentNullException_WhenLoggerIsNull() var serviceProviderMock = new Mock(); // Act && Assert - Assert.Throws(() => - new EFDebugLogger(cacheSettingsMock.Object, null!, serviceProviderMock.Object)); + Assert.Throws(() + => new EFDebugLogger(cacheSettingsMock.Object, null!, serviceProviderMock.Object)); } [Fact] @@ -67,8 +65,13 @@ public void EFDebugLogger_EnablesLogging_WhenCacheSettingsEnableLoggingIsTrue() var loggerMock = new Mock>(); var serviceProviderMock = new Mock(); - cacheSettingsMock.Setup(c => c.Value).Returns(new EFCoreSecondLevelCacheSettings { EnableLogging = true }); - loggerMock.Setup(l => l.IsEnabled(LogLevel.Debug)).Returns(true); + cacheSettingsMock.Setup(c => c.Value) + .Returns(new EFCoreSecondLevelCacheSettings + { + EnableLogging = true + }); + + loggerMock.Setup(l => l.IsEnabled(LogLevel.Debug)).Returns(value: true); // Act var logger = new EFDebugLogger(cacheSettingsMock.Object, loggerMock.Object, serviceProviderMock.Object); @@ -85,7 +88,11 @@ public void EFDebugLogger_DisablesLogging_WhenCacheSettingsEnableLoggingIsFalse( var loggerMock = new Mock>(); var serviceProviderMock = new Mock(); - cacheSettingsMock.Setup(c => c.Value).Returns(new EFCoreSecondLevelCacheSettings { EnableLogging = false }); + cacheSettingsMock.Setup(c => c.Value) + .Returns(new EFCoreSecondLevelCacheSettings + { + EnableLogging = false + }); // Act var logger = new EFDebugLogger(cacheSettingsMock.Object, loggerMock.Object, serviceProviderMock.Object); @@ -98,16 +105,14 @@ public void EFDebugLogger_DisablesLogging_WhenCacheSettingsEnableLoggingIsFalse( public void NotifyCacheableEvent_InvokesCacheableEvent_WhenLoggerIsEnabled() { // Arrange && Act - _debugLogger.NotifyCacheableEvent(CacheableLogEventId.CachingSystemStarted, "TestMessage", "TestCommand"); + _debugLogger.NotifyCacheableEvent(CacheableLogEventId.CachingSystemStarted, message: "TestMessage", + commandText: "TestCommand", efCacheKey: null); // Assert - _cacheableEventMock.Verify(e => e.Invoke(It.Is( - x => - x.EventId == CacheableLogEventId.CachingSystemStarted - && x.Message == "TestMessage" - && x.CommandText == "TestCommand" - && x.ServiceProvider == _serviceProviderMock.Object)), - Times.Once); + _cacheableEventMock.Verify( + e => e.Invoke(It.Is(x + => x.EventId == CacheableLogEventId.CachingSystemStarted && x.Message == "TestMessage" && + x.CommandText == "TestCommand" && x.ServiceProvider == _serviceProviderMock.Object)), Times.Once); } [Fact] @@ -119,13 +124,19 @@ public void NotifyCacheableEvent_DoesNotInvokeCacheableEvent_WhenLoggerIsDisable var serviceProviderMock = new Mock(); var cacheableEventMock = new Mock>(); - cacheSettingsMock.Setup(c => c.Value).Returns(new EFCoreSecondLevelCacheSettings { EnableLogging = false }); + cacheSettingsMock.Setup(c => c.Value) + .Returns(new EFCoreSecondLevelCacheSettings + { + EnableLogging = false + }); + cacheSettingsMock.Object.Value.CacheableEvent = cacheableEventMock.Object; var logger = new EFDebugLogger(cacheSettingsMock.Object, loggerMock.Object, serviceProviderMock.Object); // Act - logger.NotifyCacheableEvent(CacheableLogEventId.CachingSystemStarted, "TestMessage", "TestCommand"); + logger.NotifyCacheableEvent(CacheableLogEventId.CachingSystemStarted, message: "TestMessage", + commandText: "TestCommand", efCacheKey: null); // Assert cacheableEventMock.Verify(e => e.Invoke(It.IsAny()), Times.Never); @@ -140,13 +151,19 @@ public void NotifyCacheableEvent_DoesNotInvokeCacheableEvent_WhenCacheableEventI var loggerMock = new Mock>(); var cacheableEventMock = new Mock>(); - cacheSettingsMock.Setup(c => c.Value).Returns(new EFCoreSecondLevelCacheSettings { EnableLogging = true }); - loggerMock.Setup(l => l.IsEnabled(LogLevel.Debug)).Returns(true); + cacheSettingsMock.Setup(c => c.Value) + .Returns(new EFCoreSecondLevelCacheSettings + { + EnableLogging = true + }); + + loggerMock.Setup(l => l.IsEnabled(LogLevel.Debug)).Returns(value: true); var logger = new EFDebugLogger(cacheSettingsMock.Object, loggerMock.Object, serviceProviderMock.Object); // Act - logger.NotifyCacheableEvent(CacheableLogEventId.CachingSystemStarted, "TestMessage", "TestCommand"); + logger.NotifyCacheableEvent(CacheableLogEventId.CachingSystemStarted, message: "TestMessage", + commandText: "TestCommand", efCacheKey: null); // Assert cacheableEventMock.Verify(e => e.Invoke(It.IsAny()), Times.Never); @@ -159,14 +176,12 @@ public void NotifyCacheInvalidation_InvokesEFCacheInvalidationInfo() var cacheDependencies = new HashSet(); // Act - _debugLogger.NotifyCacheInvalidation(true, cacheDependencies); + _debugLogger.NotifyCacheInvalidation(clearAllCachedEntries: true, cacheDependencies); // Assert - _cacheInvalidationEventMock.Verify(e => e.Invoke(It.Is( - x => - x.CacheDependencies == cacheDependencies - && x.ClearAllCachedEntries == true - && x.ServiceProvider == _serviceProviderMock.Object)), - Times.Once); + _cacheInvalidationEventMock.Verify( + e => e.Invoke(It.Is(x + => x.CacheDependencies == cacheDependencies && x.ClearAllCachedEntries == true && + x.ServiceProvider == _serviceProviderMock.Object)), Times.Once); } } \ No newline at end of file