huahaofeng
/
aspnetcore
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

#189 Reduce noise for load and commit logs.

This commit is contained in:
Chris Ross (ASP.NET) 2017-09-28 12:21:31 -07:00
parent 0f71fde18a
commit be6b099f6c
4 changed files with 392 additions and 25 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

76
src/Microsoft.AspNetCore.Session/DistributedSession.cs
View File

@ -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;
}
}
}
}

52
src/Microsoft.AspNetCore.Session/LoggingExtensions.cs
View File

@ -14,6 +14,11 @@ namespace Microsoft.Extensions.Logging
private static Action<ILogger, string, string, int, Exception> _sessionStored;
private static Action<ILogger, string, Exception> _sessionCacheReadException;
private static Action<ILogger, Exception> _errorUnprotectingCookie;
private static Action<ILogger, Exception> _sessionLoadingTimeout;
private static Action<ILogger, Exception> _sessionCommitTimeout;
private static Action<ILogger, Exception> _sessionCommitCanceled;
private static Action<ILogger, Exception> _sessionRefreshTimeout;
private static Action<ILogger, Exception> _sessionRefreshCanceled;
static LoggingExtensions()
{
@ -23,7 +28,7 @@ namespace Microsoft.Extensions.Logging
formatString: "Error closing the session.");
_accessingExpiredSession = LoggerMessage.Define<string>(
eventId: 2,
logLevel: LogLevel.Warning,
logLevel: LogLevel.Information,
formatString: "Accessing expired session, Key:{sessionKey}");
_sessionStarted = LoggerMessage.Define<string, string>(
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);
}
}
}

4
src/Microsoft.AspNetCore.Session/SessionMiddleware.cs
View File

@ -116,6 +116,10 @@ namespace Microsoft.AspNetCore.Session
{
await feature.Session.CommitAsync(context.RequestAborted);
}
catch (OperationCanceledException)
{
_logger.SessionCommitCanceled();
}
catch (Exception ex)
{
_logger.ErrorClosingTheSession(ex);

285
test/Microsoft.AspNetCore.Session.Tests/SessionTests.cs
View File

@ -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<DistributedSession>,
@ -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<DistributedSession>,
TestSink.EnableWithTypeName<DistributedSession>);
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var builder = new WebHostBuilder()
.Configure(app =>
{
app.UseSession();
app.Run(async context =>
{
await Assert.ThrowsAsync<InvalidOperationException>(() => 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<IDistributedCache>(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<DistributedSession>,
TestSink.EnableWithTypeName<DistributedSession>);
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<OperationCanceledException>(() => context.Session.LoadAsync());
});
})
.ConfigureServices(services =>
{
services.AddSingleton(typeof(ILoggerFactory), loggerFactory);
services.AddSingleton<IDistributedCache>(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<DistributedSession>,
TestSink.EnableWithTypeName<DistributedSession>);
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<OperationCanceledException>(() => context.Session.LoadAsync(token));
});
})
.ConfigureServices(services =>
{
services.AddSingleton(typeof(ILoggerFactory), loggerFactory);
services.AddSingleton<IDistributedCache>(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<IDistributedCache>(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<OperationCanceledException>(() => context.Session.CommitAsync(token));
context.RequestAborted = token;
});
})
.ConfigureServices(services =>
{
services.AddSingleton(typeof(ILoggerFactory), loggerFactory);
services.AddSingleton<IDistributedCache>(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<byte[]> GetAsync(string key, CancellationToken token = default(CancellationToken)) => _cache.GetAsync(key);
public Task<byte[]> 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);
}
}