Skip to content
This repository was archived by the owner on Nov 22, 2018. It is now read-only.

Reduce noise for commit logs. #195

Merged
merged 1 commit into from
Oct 5, 2017
Merged

Reduce noise for commit logs. #195

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions src/Microsoft.AspNetCore.Session/DistributedSession.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -239,6 +241,9 @@ private void Load()
_logger.SessionStarted(_sessionKey, Id);
}
}
catch (OperationCanceledException)
{
}
catch (Exception exception)
{
_logger.SessionCacheReadException(_sessionKey, exception);
Expand Down
12 changes: 11 additions & 1 deletion src/Microsoft.AspNetCore.Session/LoggingExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ internal static class LoggingExtensions
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> _sessionCommitCanceled;

static LoggingExtensions()
{
Expand All @@ -23,7 +24,7 @@ static LoggingExtensions()
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,
Expand All @@ -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)
Expand Down Expand Up @@ -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);
}
}
}
4 changes: 4 additions & 0 deletions src/Microsoft.AspNetCore.Session/SessionMiddleware.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
233 changes: 229 additions & 4 deletions test/Microsoft.AspNetCore.Session.Tests/SessionTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<DistributedSession>,
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -603,7 +603,90 @@ public async Task SessionLogsCacheReadException()
}

[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 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 =>
Expand Down Expand Up @@ -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<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);

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()
{
Expand Down Expand Up @@ -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)
{
Expand All @@ -732,25 +928,54 @@ public byte[] Get(string key)
}
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(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);
}
}
Expand Down