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

Commit f49f9ed

Browse files
TratcherTratcher
committed
#194 Reduce noise for commit logs.
1 parent c989623 commit f49f9ed

File tree

4 files changed

+249
-5
lines changed

4 files changed

+249
-5
lines changed

‎src/Microsoft.AspNetCore.Session/DistributedSession.cs

+5
Original file line numberDiff line numberDiff line change
@@ -231,6 +231,8 @@ private void Load()
231231
{
232232
if (_logger.IsEnabled(LogLevel.Information))
233233
{
234+
// This operation is only so we can log if the session already existed.
235+
// Log and ignore failures.
234236
try
235237
{
236238
var data = await _cache.GetAsync(_sessionKey, cts.Token);
@@ -239,6 +241,9 @@ private void Load()
239241
_logger.SessionStarted(_sessionKey, Id);
240242
}
241243
}
244+
catch (OperationCanceledException)
245+
{
246+
}
242247
catch (Exception exception)
243248
{
244249
_logger.SessionCacheReadException(_sessionKey, exception);

‎src/Microsoft.AspNetCore.Session/LoggingExtensions.cs

+11-1
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ internal static class LoggingExtensions
1414
private static Action<ILogger, string, string, int, Exception> _sessionStored;
1515
private static Action<ILogger, string, Exception> _sessionCacheReadException;
1616
private static Action<ILogger, Exception> _errorUnprotectingCookie;
17+
private static Action<ILogger, Exception> _sessionCommitCanceled;
1718

1819
static LoggingExtensions()
1920
{
@@ -23,7 +24,7 @@ static LoggingExtensions()
2324
formatString: "Error closing the session.");
2425
_accessingExpiredSession = LoggerMessage.Define<string>(
2526
eventId: 2,
26-
logLevel: LogLevel.Warning,
27+
logLevel: LogLevel.Information,
2728
formatString: "Accessing expired session, Key:{sessionKey}");
2829
_sessionStarted = LoggerMessage.Define<string, string>(
2930
eventId: 3,
@@ -45,6 +46,10 @@ static LoggingExtensions()
4546
eventId: 7,
4647
logLevel: LogLevel.Warning,
4748
formatString: "Error unprotecting the session cookie.");
49+
_sessionCommitCanceled = LoggerMessage.Define(
50+
eventId: 10,
51+
logLevel: LogLevel.Information,
52+
formatString: "Committing the session was canceled.");
4853
}
4954

5055
public static void ErrorClosingTheSession(this ILogger logger, Exception exception)
@@ -81,5 +86,10 @@ public static void ErrorUnprotectingSessionCookie(this ILogger logger, Exception
8186
{
8287
_errorUnprotectingCookie(logger, exception);
8388
}
89+
90+
public static void SessionCommitCanceled(this ILogger logger)
91+
{
92+
_sessionCommitCanceled(logger, null);
93+
}
8494
}
8595
}

‎src/Microsoft.AspNetCore.Session/SessionMiddleware.cs

+4
Original file line numberDiff line numberDiff line change
@@ -116,6 +116,10 @@ public async Task Invoke(HttpContext context)
116116
{
117117
await feature.Session.CommitAsync(context.RequestAborted);
118118
}
119+
catch (OperationCanceledException)
120+
{
121+
_logger.SessionCommitCanceled();
122+
}
119123
catch (Exception ex)
120124
{
121125
_logger.ErrorClosingTheSession(ex);

‎test/Microsoft.AspNetCore.Session.Tests/SessionTests.cs

+229-4
Original file line numberDiff line numberDiff line change
@@ -331,7 +331,7 @@ public async Task SessionStart_LogsInformation()
331331
}
332332

333333
[Fact]
334-
public async Task ExpiredSession_LogsWarning()
334+
public async Task ExpiredSession_LogsInfo()
335335
{
336336
var sink = new TestSink(
337337
TestSink.EnableWithTypeName<DistributedSession>,
@@ -388,7 +388,7 @@ public async Task ExpiredSession_LogsWarning()
388388
Assert.Contains("expired", sessionLogMessages[2].State.ToString());
389389
Assert.Equal(LogLevel.Information, sessionLogMessages[0].LogLevel);
390390
Assert.Equal(LogLevel.Debug, sessionLogMessages[1].LogLevel);
391-
Assert.Equal(LogLevel.Warning, sessionLogMessages[2].LogLevel);
391+
Assert.Equal(LogLevel.Information, sessionLogMessages[2].LogLevel);
392392
}
393393

394394
[Fact]
@@ -603,7 +603,90 @@ public async Task SessionLogsCacheReadException()
603603
}
604604

605605
[Fact]
606-
public async Task SessionLogsCacheWriteException()
606+
public async Task SessionLogsCacheLoadAsyncException()
607+
{
608+
var sink = new TestSink(
609+
TestSink.EnableWithTypeName<DistributedSession>,
610+
TestSink.EnableWithTypeName<DistributedSession>);
611+
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
612+
var builder = new WebHostBuilder()
613+
.Configure(app =>
614+
{
615+
app.UseSession();
616+
app.Run(async context =>
617+
{
618+
await Assert.ThrowsAsync<InvalidOperationException>(() => context.Session.LoadAsync());
619+
Assert.False(context.Session.IsAvailable);
620+
Assert.Equal(string.Empty, context.Session.Id);
621+
Assert.False(context.Session.Keys.Any());
622+
});
623+
})
624+
.ConfigureServices(services =>
625+
{
626+
services.AddSingleton(typeof(ILoggerFactory), loggerFactory);
627+
services.AddSingleton<IDistributedCache>(new UnreliableCache(new MemoryCache(new MemoryCacheOptions()))
628+
{
629+
DisableGet = true
630+
});
631+
services.AddSession();
632+
});
633+
634+
using (var server = new TestServer(builder))
635+
{
636+
var client = server.CreateClient();
637+
var response = await client.GetAsync(string.Empty);
638+
response.EnsureSuccessStatusCode();
639+
}
640+
641+
var sessionLogMessages = sink.Writes;
642+
643+
Assert.Single(sessionLogMessages);
644+
Assert.Contains("Session cache read exception", sessionLogMessages[0].State.ToString());
645+
Assert.Equal(LogLevel.Error, sessionLogMessages[0].LogLevel);
646+
}
647+
648+
[Fact]
649+
public async Task SessionLoadAsyncCanceledException()
650+
{
651+
var sink = new TestSink(
652+
TestSink.EnableWithTypeName<DistributedSession>,
653+
TestSink.EnableWithTypeName<DistributedSession>);
654+
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
655+
var builder = new WebHostBuilder()
656+
.Configure(app =>
657+
{
658+
app.UseSession();
659+
app.Run(async context =>
660+
{
661+
var cts = new CancellationTokenSource();
662+
var token = cts.Token;
663+
cts.Cancel();
664+
await Assert.ThrowsAsync<OperationCanceledException>(() => context.Session.LoadAsync(token));
665+
});
666+
})
667+
.ConfigureServices(services =>
668+
{
669+
services.AddSingleton(typeof(ILoggerFactory), loggerFactory);
670+
services.AddSingleton<IDistributedCache>(new UnreliableCache(new MemoryCache(new MemoryCacheOptions()))
671+
{
672+
DelayGetAsync = true
673+
});
674+
services.AddSession();
675+
});
676+
677+
using (var server = new TestServer(builder))
678+
{
679+
var client = server.CreateClient();
680+
var response = await client.GetAsync(string.Empty);
681+
response.EnsureSuccessStatusCode();
682+
}
683+
684+
var sessionLogMessages = sink.Writes;
685+
Assert.Empty(sessionLogMessages);
686+
}
687+
688+
[Fact]
689+
public async Task SessionLogsCacheCommitException()
607690
{
608691
var sink = new TestSink(
609692
writeContext =>
@@ -655,6 +738,116 @@ public async Task SessionLogsCacheWriteException()
655738
Assert.Equal(LogLevel.Error, sessionMiddlewareLogMessage.LogLevel);
656739
}
657740

741+
[Fact]
742+
public async Task SessionLogsCacheCommitTimeoutException()
743+
{
744+
var sink = new TestSink(
745+
writeContext =>
746+
{
747+
return writeContext.LoggerName.Equals(typeof(SessionMiddleware).FullName)
748+
|| writeContext.LoggerName.Equals(typeof(DistributedSession).FullName);
749+
},
750+
beginScopeContext =>
751+
{
752+
return beginScopeContext.LoggerName.Equals(typeof(SessionMiddleware).FullName)
753+
|| beginScopeContext.LoggerName.Equals(typeof(DistributedSession).FullName);
754+
});
755+
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
756+
var builder = new WebHostBuilder()
757+
.Configure(app =>
758+
{
759+
app.UseSession(new SessionOptions()
760+
{
761+
IOTimeout = TimeSpan.FromSeconds(0.5)
762+
});
763+
app.Run(context =>
764+
{
765+
context.Session.SetInt32("key", 0);
766+
return Task.FromResult(0);
767+
});
768+
})
769+
.ConfigureServices(services =>
770+
{
771+
services.AddSingleton(typeof(ILoggerFactory), loggerFactory);
772+
services.AddSingleton<IDistributedCache>(new UnreliableCache(new MemoryCache(new MemoryCacheOptions()))
773+
{
774+
DelaySetAsync = true
775+
});
776+
services.AddSession();
777+
});
778+
779+
using (var server = new TestServer(builder))
780+
{
781+
var client = server.CreateClient();
782+
var response = await client.GetAsync(string.Empty);
783+
response.EnsureSuccessStatusCode();
784+
}
785+
786+
var sessionLogMessages = sink.Writes.Where(message => message.LoggerName.Equals(typeof(DistributedSession).FullName, StringComparison.Ordinal)).ToList();
787+
788+
Assert.Contains("Session started", sessionLogMessages[0].State.ToString());
789+
Assert.Equal(LogLevel.Information, sessionLogMessages[0].LogLevel);
790+
791+
var sessionMiddlewareLogs = sink.Writes.Where(message => message.LoggerName.Equals(typeof(SessionMiddleware).FullName, StringComparison.Ordinal)).ToList();
792+
793+
Assert.Contains("Committing the session was canceled.", sessionMiddlewareLogs[0].State.ToString());
794+
Assert.Equal(LogLevel.Information, sessionMiddlewareLogs[0].LogLevel);
795+
}
796+
797+
[Fact]
798+
public async Task SessionLogsCacheCommitCanceledException()
799+
{
800+
var sink = new TestSink(
801+
writeContext =>
802+
{
803+
return writeContext.LoggerName.Equals(typeof(SessionMiddleware).FullName)
804+
|| writeContext.LoggerName.Equals(typeof(DistributedSession).FullName);
805+
},
806+
beginScopeContext =>
807+
{
808+
return beginScopeContext.LoggerName.Equals(typeof(SessionMiddleware).FullName)
809+
|| beginScopeContext.LoggerName.Equals(typeof(DistributedSession).FullName);
810+
});
811+
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
812+
var builder = new WebHostBuilder()
813+
.Configure(app =>
814+
{
815+
app.UseSession();
816+
app.Run(async context =>
817+
{
818+
context.Session.SetInt32("key", 0);
819+
var cts = new CancellationTokenSource();
820+
var token = cts.Token;
821+
cts.Cancel();
822+
await Assert.ThrowsAsync<OperationCanceledException>(() => context.Session.CommitAsync(token));
823+
context.RequestAborted = token;
824+
});
825+
})
826+
.ConfigureServices(services =>
827+
{
828+
services.AddSingleton(typeof(ILoggerFactory), loggerFactory);
829+
services.AddSingleton<IDistributedCache>(new UnreliableCache(new MemoryCache(new MemoryCacheOptions()))
830+
{
831+
DelaySetAsync = true
832+
});
833+
services.AddSession();
834+
});
835+
836+
using (var server = new TestServer(builder))
837+
{
838+
var client = server.CreateClient();
839+
var response = await client.GetAsync(string.Empty);
840+
response.EnsureSuccessStatusCode();
841+
}
842+
843+
Assert.Empty(sink.Writes.Where(message => message.LoggerName.Equals(typeof(DistributedSession).FullName, StringComparison.Ordinal)));
844+
845+
var sessionMiddlewareLogs = sink.Writes.Where(message => message.LoggerName.Equals(typeof(SessionMiddleware).FullName, StringComparison.Ordinal)).ToList();
846+
847+
Assert.Contains("Committing the session was canceled.", sessionMiddlewareLogs[0].State.ToString());
848+
Assert.Equal(LogLevel.Information, sessionMiddlewareLogs[0].LogLevel);
849+
}
850+
658851
[Fact]
659852
public async Task SessionLogsCacheRefreshException()
660853
{
@@ -718,6 +911,9 @@ private class UnreliableCache : IDistributedCache
718911
public bool DisableGet { get; set; }
719912
public bool DisableSetAsync { get; set; }
720913
public bool DisableRefreshAsync { get; set; }
914+
public bool DelayGetAsync { get; set; }
915+
public bool DelaySetAsync { get; set; }
916+
public bool DelayRefreshAsync { get; set; }
721917

722918
public UnreliableCache(IMemoryCache memoryCache)
723919
{
@@ -732,25 +928,54 @@ public byte[] Get(string key)
732928
}
733929
return _cache.Get(key);
734930
}
735-
public Task<byte[]> GetAsync(string key, CancellationToken token = default(CancellationToken)) => _cache.GetAsync(key);
931+
932+
public Task<byte[]> GetAsync(string key, CancellationToken token = default(CancellationToken))
933+
{
934+
if (DisableGet)
935+
{
936+
throw new InvalidOperationException();
937+
}
938+
if (DelayGetAsync)
939+
{
940+
token.WaitHandle.WaitOne(TimeSpan.FromSeconds(10));
941+
token.ThrowIfCancellationRequested();
942+
}
943+
return _cache.GetAsync(key, token);
944+
}
945+
736946
public void Refresh(string key) => _cache.Refresh(key);
947+
737948
public Task RefreshAsync(string key, CancellationToken token = default(CancellationToken))
738949
{
739950
if (DisableRefreshAsync)
740951
{
741952
throw new InvalidOperationException();
742953
}
954+
if (DelayRefreshAsync)
955+
{
956+
token.WaitHandle.WaitOne(TimeSpan.FromSeconds(10));
957+
token.ThrowIfCancellationRequested();
958+
}
743959
return _cache.RefreshAsync(key);
744960
}
961+
745962
public void Remove(string key) => _cache.Remove(key);
963+
746964
public Task RemoveAsync(string key, CancellationToken token = default(CancellationToken)) => _cache.RemoveAsync(key);
965+
747966
public void Set(string key, byte[] value, DistributedCacheEntryOptions options) => _cache.Set(key, value, options);
967+
748968
public Task SetAsync(string key, byte[] value, DistributedCacheEntryOptions options, CancellationToken token = default(CancellationToken))
749969
{
750970
if (DisableSetAsync)
751971
{
752972
throw new InvalidOperationException();
753973
}
974+
if (DelaySetAsync)
975+
{
976+
token.WaitHandle.WaitOne(TimeSpan.FromSeconds(10));
977+
token.ThrowIfCancellationRequested();
978+
}
754979
return _cache.SetAsync(key, value, options);
755980
}
756981
}

0 commit comments

Comments
 (0)