diff --git a/src/Microsoft.AspNetCore.Session/DistributedSession.cs b/src/Microsoft.AspNetCore.Session/DistributedSession.cs index 1f9fa7fa87..76ab3f3cf5 100644 --- a/src/Microsoft.AspNetCore.Session/DistributedSession.cs +++ b/src/Microsoft.AspNetCore.Session/DistributedSession.cs @@ -198,22 +198,34 @@ namespace Microsoft.AspNetCore.Session } // This will throw if called directly and a failure occurs. The user is expected to handle the failures. - public async Task LoadAsync(CancellationToken cancellationToken = default(CancellationToken)) + public async Task LoadAsync(CancellationToken cancellationToken = default) { - cancellationToken.ThrowIfCancellationRequested(); if (!_loaded) { using (var timeout = new CancellationTokenSource(_ioTimeout)) { var cts = CancellationTokenSource.CreateLinkedTokenSource(timeout.Token, cancellationToken); - var data = await _cache.GetAsync(_sessionKey, cts.Token); - if (data != null) + try { - Deserialize(new MemoryStream(data)); + cts.Token.ThrowIfCancellationRequested(); + var data = await _cache.GetAsync(_sessionKey, cts.Token); + if (data != null) + { + Deserialize(new MemoryStream(data)); + } + else if (!_isNewSessionKey) + { + _logger.AccessingExpiredSession(_sessionKey); + } } - else if (!_isNewSessionKey) + catch (OperationCanceledException oex) { - _logger.AccessingExpiredSession(_sessionKey); + if (timeout.Token.IsCancellationRequested) + { + _logger.SessionLoadingTimeout(); + throw new OperationCanceledException("Timed out loading the session.", oex, timeout.Token); + } + throw; } } _isAvailable = true; @@ -221,9 +233,8 @@ namespace Microsoft.AspNetCore.Session } } - public async Task CommitAsync(CancellationToken cancellationToken = default(CancellationToken)) + public async Task CommitAsync(CancellationToken cancellationToken = default) { - cancellationToken.ThrowIfCancellationRequested(); using (var timeout = new CancellationTokenSource(_ioTimeout)) { var cts = CancellationTokenSource.CreateLinkedTokenSource(timeout.Token, cancellationToken); @@ -231,14 +242,20 @@ namespace Microsoft.AspNetCore.Session { if (_logger.IsEnabled(LogLevel.Information)) { + // This operation is only so we can log if the session already existed. + // Log and ignore failures. try { + cts.Token.ThrowIfCancellationRequested(); var data = await _cache.GetAsync(_sessionKey, cts.Token); if (data == null) { _logger.SessionStarted(_sessionKey, Id); } } + catch (OperationCanceledException) + { + } catch (Exception exception) { _logger.SessionCacheReadException(_sessionKey, exception); @@ -248,17 +265,42 @@ namespace Microsoft.AspNetCore.Session var stream = new MemoryStream(); Serialize(stream); - await _cache.SetAsync( - _sessionKey, - stream.ToArray(), - new DistributedCacheEntryOptions().SetSlidingExpiration(_idleTimeout), - cts.Token); - _isModified = false; - _logger.SessionStored(_sessionKey, Id, _store.Count); + try + { + cts.Token.ThrowIfCancellationRequested(); + await _cache.SetAsync( + _sessionKey, + stream.ToArray(), + new DistributedCacheEntryOptions().SetSlidingExpiration(_idleTimeout), + cts.Token); + _isModified = false; + _logger.SessionStored(_sessionKey, Id, _store.Count); + } + catch (OperationCanceledException oex) + { + if (timeout.Token.IsCancellationRequested) + { + _logger.SessionCommitTimeout(); + throw new OperationCanceledException("Timed out committing the session.", oex, timeout.Token); + } + throw; + } } else { - await _cache.RefreshAsync(_sessionKey, cts.Token); + try + { + await _cache.RefreshAsync(_sessionKey, cts.Token); + } + catch (OperationCanceledException oex) + { + if (timeout.Token.IsCancellationRequested) + { + _logger.SessionRefreshTimeout(); + throw new OperationCanceledException("Timed out refreshing the session.", oex, timeout.Token); + } + throw; + } } } } diff --git a/src/Microsoft.AspNetCore.Session/LoggingExtensions.cs b/src/Microsoft.AspNetCore.Session/LoggingExtensions.cs index c6780a7dfc..2552ac20de 100644 --- a/src/Microsoft.AspNetCore.Session/LoggingExtensions.cs +++ b/src/Microsoft.AspNetCore.Session/LoggingExtensions.cs @@ -14,6 +14,11 @@ namespace Microsoft.Extensions.Logging private static Action _sessionStored; private static Action _sessionCacheReadException; private static Action _errorUnprotectingCookie; + private static Action _sessionLoadingTimeout; + private static Action _sessionCommitTimeout; + private static Action _sessionCommitCanceled; + private static Action _sessionRefreshTimeout; + private static Action _sessionRefreshCanceled; static LoggingExtensions() { @@ -23,7 +28,7 @@ namespace Microsoft.Extensions.Logging 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 +50,26 @@ namespace Microsoft.Extensions.Logging eventId: 7, logLevel: LogLevel.Warning, formatString: "Error unprotecting the session cookie."); + _sessionLoadingTimeout = LoggerMessage.Define( + eventId: 8, + logLevel: LogLevel.Warning, + formatString: "Loading the session timed out."); + _sessionCommitTimeout = LoggerMessage.Define( + eventId: 9, + logLevel: LogLevel.Warning, + formatString: "Committing the session timed out."); + _sessionCommitCanceled = LoggerMessage.Define( + eventId: 10, + logLevel: LogLevel.Information, + formatString: "Committing the session was canceled."); + _sessionRefreshTimeout = LoggerMessage.Define( + eventId: 11, + logLevel: LogLevel.Warning, + formatString: "Refreshing the session timed out."); + _sessionRefreshCanceled = LoggerMessage.Define( + eventId: 12, + logLevel: LogLevel.Information, + formatString: "Refreshing the session was canceled."); } public static void ErrorClosingTheSession(this ILogger logger, Exception exception) @@ -81,5 +106,30 @@ namespace Microsoft.Extensions.Logging { _errorUnprotectingCookie(logger, exception); } + + public static void SessionLoadingTimeout(this ILogger logger) + { + _sessionLoadingTimeout(logger, null); + } + + public static void SessionCommitTimeout(this ILogger logger) + { + _sessionCommitTimeout(logger, null); + } + + public static void SessionCommitCanceled(this ILogger logger) + { + _sessionCommitCanceled(logger, null); + } + + public static void SessionRefreshTimeout(this ILogger logger) + { + _sessionRefreshTimeout(logger, null); + } + + public static void SessionRefreshCanceled(this ILogger logger) + { + _sessionRefreshCanceled(logger, null); + } } } diff --git a/src/Microsoft.AspNetCore.Session/SessionMiddleware.cs b/src/Microsoft.AspNetCore.Session/SessionMiddleware.cs index 2dbc0531c9..bd74afa9cb 100644 --- a/src/Microsoft.AspNetCore.Session/SessionMiddleware.cs +++ b/src/Microsoft.AspNetCore.Session/SessionMiddleware.cs @@ -116,6 +116,10 @@ namespace Microsoft.AspNetCore.Session { 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 58ccdcd8d6..429e141294 100644 --- a/test/Microsoft.AspNetCore.Session.Tests/SessionTests.cs +++ b/test/Microsoft.AspNetCore.Session.Tests/SessionTests.cs @@ -328,7 +328,7 @@ namespace Microsoft.AspNetCore.Session } [Fact] - public async Task ExpiredSession_LogsWarning() + public async Task ExpiredSession_LogsInfo() { var sink = new TestSink( TestSink.EnableWithTypeName, @@ -385,7 +385,7 @@ namespace Microsoft.AspNetCore.Session 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] @@ -599,7 +599,133 @@ namespace Microsoft.AspNetCore.Session } [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 SessionLogsCacheLoadAsyncTimeoutException() + { + var sink = new TestSink( + TestSink.EnableWithTypeName, + TestSink.EnableWithTypeName); + var loggerFactory = new TestLoggerFactory(sink, enabled: true); + var builder = new WebHostBuilder() + .Configure(app => + { + app.UseSession(new SessionOptions() + { + IOTimeout = TimeSpan.FromSeconds(0.5) + }); + app.Run(async context => + { + await Assert.ThrowsAsync(() => context.Session.LoadAsync()); + }); + }) + .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.Single(sessionLogMessages); + Assert.Contains("Loading the session timed out.", sessionLogMessages[0].State.ToString()); + Assert.Equal(LogLevel.Warning, 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 => @@ -651,6 +777,119 @@ namespace Microsoft.AspNetCore.Session 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); + + Assert.Contains("Committing the session timed out.", sessionLogMessages[1].State.ToString()); + Assert.Equal(LogLevel.Warning, sessionLogMessages[1].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() { @@ -714,6 +953,9 @@ namespace Microsoft.AspNetCore.Session 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) { @@ -728,25 +970,54 @@ namespace Microsoft.AspNetCore.Session } return _cache.Get(key); } - public Task GetAsync(string key, CancellationToken token = default(CancellationToken)) => _cache.GetAsync(key); + + public Task GetAsync(string key, CancellationToken token = default) + { + 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)) + + public Task RefreshAsync(string key, CancellationToken token = default) { 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 Task RemoveAsync(string key, CancellationToken token = default) => _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)) + + public Task SetAsync(string key, byte[] value, DistributedCacheEntryOptions options, CancellationToken token = default) { if (DisableSetAsync) { throw new InvalidOperationException(); } + if (DelaySetAsync) + { + token.WaitHandle.WaitOne(TimeSpan.FromSeconds(10)); + token.ThrowIfCancellationRequested(); + } return _cache.SetAsync(key, value, options); } }