diff --git a/src/Microsoft.AspNetCore.Session/DistributedSession.cs b/src/Microsoft.AspNetCore.Session/DistributedSession.cs index 1f9fa7f..22edd4d 100644 --- a/src/Microsoft.AspNetCore.Session/DistributedSession.cs +++ b/src/Microsoft.AspNetCore.Session/DistributedSession.cs @@ -231,6 +231,8 @@ private void Load() { if (_logger.IsEnabled(LogLevel.Information)) { + // This operation is only so we can log if the session already existed. + // Log and ignore failures. try { var data = await _cache.GetAsync(_sessionKey, cts.Token); @@ -239,6 +241,9 @@ private void Load() _logger.SessionStarted(_sessionKey, Id); } } + catch (OperationCanceledException) + { + } catch (Exception exception) { _logger.SessionCacheReadException(_sessionKey, exception); diff --git a/src/Microsoft.AspNetCore.Session/LoggingExtensions.cs b/src/Microsoft.AspNetCore.Session/LoggingExtensions.cs index c6780a7..e1309e9 100644 --- a/src/Microsoft.AspNetCore.Session/LoggingExtensions.cs +++ b/src/Microsoft.AspNetCore.Session/LoggingExtensions.cs @@ -14,6 +14,7 @@ internal static class LoggingExtensions private static Action _sessionStored; private static Action _sessionCacheReadException; private static Action _errorUnprotectingCookie; + private static Action _sessionCommitCanceled; static LoggingExtensions() { @@ -23,7 +24,7 @@ static LoggingExtensions() formatString: "Error closing the session."); _accessingExpiredSession = LoggerMessage.Define( eventId: 2, - logLevel: LogLevel.Warning, + logLevel: LogLevel.Information, formatString: "Accessing expired session, Key:{sessionKey}"); _sessionStarted = LoggerMessage.Define( eventId: 3, @@ -45,6 +46,10 @@ static LoggingExtensions() eventId: 7, logLevel: LogLevel.Warning, formatString: "Error unprotecting the session cookie."); + _sessionCommitCanceled = LoggerMessage.Define( + eventId: 10, + logLevel: LogLevel.Information, + formatString: "Committing the session was canceled."); } public static void ErrorClosingTheSession(this ILogger logger, Exception exception) @@ -81,5 +86,10 @@ public static void ErrorUnprotectingSessionCookie(this ILogger logger, Exception { _errorUnprotectingCookie(logger, exception); } + + public static void SessionCommitCanceled(this ILogger logger) + { + _sessionCommitCanceled(logger, null); + } } } diff --git a/src/Microsoft.AspNetCore.Session/SessionMiddleware.cs b/src/Microsoft.AspNetCore.Session/SessionMiddleware.cs index 2dbc053..bd74afa 100644 --- a/src/Microsoft.AspNetCore.Session/SessionMiddleware.cs +++ b/src/Microsoft.AspNetCore.Session/SessionMiddleware.cs @@ -116,6 +116,10 @@ public async Task Invoke(HttpContext context) { await feature.Session.CommitAsync(context.RequestAborted); } + catch (OperationCanceledException) + { + _logger.SessionCommitCanceled(); + } catch (Exception ex) { _logger.ErrorClosingTheSession(ex); diff --git a/test/Microsoft.AspNetCore.Session.Tests/SessionTests.cs b/test/Microsoft.AspNetCore.Session.Tests/SessionTests.cs index 5f28c79..04e9e69 100644 --- a/test/Microsoft.AspNetCore.Session.Tests/SessionTests.cs +++ b/test/Microsoft.AspNetCore.Session.Tests/SessionTests.cs @@ -331,7 +331,7 @@ public async Task SessionStart_LogsInformation() } [Fact] - public async Task ExpiredSession_LogsWarning() + public async Task ExpiredSession_LogsInfo() { var sink = new TestSink( TestSink.EnableWithTypeName, @@ -388,7 +388,7 @@ public async Task ExpiredSession_LogsWarning() Assert.Contains("expired", sessionLogMessages[2].State.ToString()); Assert.Equal(LogLevel.Information, sessionLogMessages[0].LogLevel); Assert.Equal(LogLevel.Debug, sessionLogMessages[1].LogLevel); - Assert.Equal(LogLevel.Warning, sessionLogMessages[2].LogLevel); + Assert.Equal(LogLevel.Information, sessionLogMessages[2].LogLevel); } [Fact] @@ -603,7 +603,90 @@ public async Task SessionLogsCacheReadException() } [Fact] - public async Task SessionLogsCacheWriteException() + public async Task SessionLogsCacheLoadAsyncException() + { + var sink = new TestSink( + TestSink.EnableWithTypeName, + TestSink.EnableWithTypeName); + var loggerFactory = new TestLoggerFactory(sink, enabled: true); + var builder = new WebHostBuilder() + .Configure(app => + { + app.UseSession(); + app.Run(async context => + { + await Assert.ThrowsAsync(() => context.Session.LoadAsync()); + Assert.False(context.Session.IsAvailable); + Assert.Equal(string.Empty, context.Session.Id); + Assert.False(context.Session.Keys.Any()); + }); + }) + .ConfigureServices(services => + { + services.AddSingleton(typeof(ILoggerFactory), loggerFactory); + services.AddSingleton(new UnreliableCache(new MemoryCache(new MemoryCacheOptions())) + { + DisableGet = true + }); + services.AddSession(); + }); + + using (var server = new TestServer(builder)) + { + var client = server.CreateClient(); + var response = await client.GetAsync(string.Empty); + response.EnsureSuccessStatusCode(); + } + + var sessionLogMessages = sink.Writes; + + Assert.Single(sessionLogMessages); + Assert.Contains("Session cache read exception", sessionLogMessages[0].State.ToString()); + Assert.Equal(LogLevel.Error, sessionLogMessages[0].LogLevel); + } + + [Fact] + public async Task SessionLoadAsyncCanceledException() + { + var sink = new TestSink( + TestSink.EnableWithTypeName, + TestSink.EnableWithTypeName); + var loggerFactory = new TestLoggerFactory(sink, enabled: true); + var builder = new WebHostBuilder() + .Configure(app => + { + app.UseSession(); + app.Run(async context => + { + var cts = new CancellationTokenSource(); + var token = cts.Token; + cts.Cancel(); + await Assert.ThrowsAsync(() => context.Session.LoadAsync(token)); + }); + }) + .ConfigureServices(services => + { + services.AddSingleton(typeof(ILoggerFactory), loggerFactory); + services.AddSingleton(new UnreliableCache(new MemoryCache(new MemoryCacheOptions())) + { + DelayGetAsync = true + }); + services.AddSession(); + }); + + using (var server = new TestServer(builder)) + { + var client = server.CreateClient(); + var response = await client.GetAsync(string.Empty); + response.EnsureSuccessStatusCode(); + } + + var sessionLogMessages = sink.Writes; + Assert.Empty(sessionLogMessages); + } + + [Fact] + public async Task SessionLogsCacheCommitException() { var sink = new TestSink( writeContext => @@ -655,6 +738,116 @@ public async Task SessionLogsCacheWriteException() Assert.Equal(LogLevel.Error, sessionMiddlewareLogMessage.LogLevel); } + [Fact] + public async Task SessionLogsCacheCommitTimeoutException() + { + var sink = new TestSink( + writeContext => + { + return writeContext.LoggerName.Equals(typeof(SessionMiddleware).FullName) + || writeContext.LoggerName.Equals(typeof(DistributedSession).FullName); + }, + beginScopeContext => + { + return beginScopeContext.LoggerName.Equals(typeof(SessionMiddleware).FullName) + || beginScopeContext.LoggerName.Equals(typeof(DistributedSession).FullName); + }); + var loggerFactory = new TestLoggerFactory(sink, enabled: true); + var builder = new WebHostBuilder() + .Configure(app => + { + app.UseSession(new SessionOptions() + { + IOTimeout = TimeSpan.FromSeconds(0.5) + }); + app.Run(context => + { + context.Session.SetInt32("key", 0); + return Task.FromResult(0); + }); + }) + .ConfigureServices(services => + { + services.AddSingleton(typeof(ILoggerFactory), loggerFactory); + services.AddSingleton(new UnreliableCache(new MemoryCache(new MemoryCacheOptions())) + { + DelaySetAsync = true + }); + services.AddSession(); + }); + + using (var server = new TestServer(builder)) + { + var client = server.CreateClient(); + var response = await client.GetAsync(string.Empty); + response.EnsureSuccessStatusCode(); + } + + var sessionLogMessages = sink.Writes.Where(message => message.LoggerName.Equals(typeof(DistributedSession).FullName, StringComparison.Ordinal)).ToList(); + + Assert.Contains("Session started", sessionLogMessages[0].State.ToString()); + Assert.Equal(LogLevel.Information, sessionLogMessages[0].LogLevel); + + var sessionMiddlewareLogs = sink.Writes.Where(message => message.LoggerName.Equals(typeof(SessionMiddleware).FullName, StringComparison.Ordinal)).ToList(); + + Assert.Contains("Committing the session was canceled.", sessionMiddlewareLogs[0].State.ToString()); + Assert.Equal(LogLevel.Information, sessionMiddlewareLogs[0].LogLevel); + } + + [Fact] + public async Task SessionLogsCacheCommitCanceledException() + { + var sink = new TestSink( + writeContext => + { + return writeContext.LoggerName.Equals(typeof(SessionMiddleware).FullName) + || writeContext.LoggerName.Equals(typeof(DistributedSession).FullName); + }, + beginScopeContext => + { + return beginScopeContext.LoggerName.Equals(typeof(SessionMiddleware).FullName) + || beginScopeContext.LoggerName.Equals(typeof(DistributedSession).FullName); + }); + var loggerFactory = new TestLoggerFactory(sink, enabled: true); + var builder = new WebHostBuilder() + .Configure(app => + { + app.UseSession(); + app.Run(async context => + { + context.Session.SetInt32("key", 0); + var cts = new CancellationTokenSource(); + var token = cts.Token; + cts.Cancel(); + await Assert.ThrowsAsync(() => context.Session.CommitAsync(token)); + context.RequestAborted = token; + }); + }) + .ConfigureServices(services => + { + services.AddSingleton(typeof(ILoggerFactory), loggerFactory); + services.AddSingleton(new UnreliableCache(new MemoryCache(new MemoryCacheOptions())) + { + DelaySetAsync = true + }); + services.AddSession(); + }); + + using (var server = new TestServer(builder)) + { + var client = server.CreateClient(); + var response = await client.GetAsync(string.Empty); + response.EnsureSuccessStatusCode(); + } + + Assert.Empty(sink.Writes.Where(message => message.LoggerName.Equals(typeof(DistributedSession).FullName, StringComparison.Ordinal))); + + var sessionMiddlewareLogs = sink.Writes.Where(message => message.LoggerName.Equals(typeof(SessionMiddleware).FullName, StringComparison.Ordinal)).ToList(); + + Assert.Contains("Committing the session was canceled.", sessionMiddlewareLogs[0].State.ToString()); + Assert.Equal(LogLevel.Information, sessionMiddlewareLogs[0].LogLevel); + } + [Fact] public async Task SessionLogsCacheRefreshException() { @@ -718,6 +911,9 @@ private class UnreliableCache : IDistributedCache public bool DisableGet { get; set; } public bool DisableSetAsync { get; set; } public bool DisableRefreshAsync { get; set; } + public bool DelayGetAsync { get; set; } + public bool DelaySetAsync { get; set; } + public bool DelayRefreshAsync { get; set; } public UnreliableCache(IMemoryCache memoryCache) { @@ -732,25 +928,54 @@ public byte[] Get(string key) } return _cache.Get(key); } - public Task GetAsync(string key, CancellationToken token = default(CancellationToken)) => _cache.GetAsync(key); + + public Task GetAsync(string key, CancellationToken token = default(CancellationToken)) + { + if (DisableGet) + { + throw new InvalidOperationException(); + } + if (DelayGetAsync) + { + token.WaitHandle.WaitOne(TimeSpan.FromSeconds(10)); + token.ThrowIfCancellationRequested(); + } + return _cache.GetAsync(key, token); + } + public void Refresh(string key) => _cache.Refresh(key); + public Task RefreshAsync(string key, CancellationToken token = default(CancellationToken)) { if (DisableRefreshAsync) { throw new InvalidOperationException(); } + if (DelayRefreshAsync) + { + token.WaitHandle.WaitOne(TimeSpan.FromSeconds(10)); + token.ThrowIfCancellationRequested(); + } return _cache.RefreshAsync(key); } + public void Remove(string key) => _cache.Remove(key); + public Task RemoveAsync(string key, CancellationToken token = default(CancellationToken)) => _cache.RemoveAsync(key); + public void Set(string key, byte[] value, DistributedCacheEntryOptions options) => _cache.Set(key, value, options); + public Task SetAsync(string key, byte[] value, DistributedCacheEntryOptions options, CancellationToken token = default(CancellationToken)) { if (DisableSetAsync) { throw new InvalidOperationException(); } + if (DelaySetAsync) + { + token.WaitHandle.WaitOne(TimeSpan.FromSeconds(10)); + token.ThrowIfCancellationRequested(); + } return _cache.SetAsync(key, value, options); } }