public async Task RouteAsync_FailOnNoAction_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
var mockActionSelector = new Mock<IActionSelector>();
mockActionSelector.Setup(a => a.SelectAsync(It.IsAny<RouteContext>()))
.Returns(Task.FromResult<ActionDescriptor>(null));
var context = CreateRouteContext(
actionSelector: mockActionSelector.Object,
loggerFactory: loggerFactory);
var handler = new MvcRouteHandler();
// Act
await handler.RouteAsync(context);
// Assert
var scope = Assert.Single(sink.Scopes);
Assert.Equal(typeof(MvcRouteHandler).FullName, scope.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", scope.Scope);
var write = Assert.Single(sink.Writes);
Assert.Equal(typeof(MvcRouteHandler).FullName, write.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", write.Scope);
var values = Assert.IsType<MvcRouteHandlerRouteAsyncValues>(write.State);
Assert.Equal("MvcRouteHandler.RouteAsync", values.Name);
Assert.False(values.ActionSelected);
Assert.False(values.ActionInvoked);
Assert.False(values.Handled);
}
public void MatchUrlGeneration_DoesNotLogData()
{
// Arrange
var sink = new TestSink();
var logger = new TestLogger(_name, sink, enabled: true);
var routeValueDictionary = new RouteValueDictionary(new { a = "value", b = "value" });
var constraints = new Dictionary<string, IRouteConstraint>
{
{"a", new PassConstraint()},
{"b", new FailConstraint()}
};
// Act
RouteConstraintMatcher.Match(
constraints: constraints,
routeValues: routeValueDictionary,
httpContext: new Mock<HttpContext>().Object,
route: new Mock<IRouter>().Object,
routeDirection: RouteDirection.UrlGeneration,
logger: logger);
// Assert
// There are no BeginScopes called.
Assert.Empty(sink.Scopes);
// There are no WriteCores called.
Assert.Empty(sink.Writes);
}
public void BeginScope_CreatesScope_WithFormatStringValues()
{
// Arrange
var testSink = new TestSink(
writeEnabled: (writeContext) => true,
beginEnabled: (beginScopeContext) => true);
var logger = new TestLogger("TestLogger", testSink, enabled: true);
var actionName = "App.Controllers.Home.Index";
var expectedStringMessage = "Executing action " + actionName;
// Act
var scope = logger.BeginScope("Executing action {ActionName}", actionName);
// Assert
Assert.Equal(1, testSink.Scopes.Count);
Assert.IsType<FormattedLogValues>(testSink.Scopes[0].Scope);
var scopeState = (FormattedLogValues)testSink.Scopes[0].Scope;
Assert.Equal(expectedStringMessage, scopeState.ToString());
var scopeProperties = scopeState.GetValues();
Assert.NotNull(scopeProperties);
Assert.Contains(scopeProperties, (kvp) =>
{
return (string.Equals(kvp.Key, "ActionName") && string.Equals(kvp.Value?.ToString(), actionName));
});
}
public async void Invoke_LogsCorrectValues_WhenNotHandled()
{
// Arrange
var expectedMessage = "Request did not match any routes.";
var isHandled = false;
var sink = new TestSink(
TestSink.EnableWithTypeName<RouterMiddleware>,
TestSink.EnableWithTypeName<RouterMiddleware>);
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var httpContext = new DefaultHttpContext();
httpContext.RequestServices = new ServiceProvider();
RequestDelegate next = (c) =>
{
return Task.FromResult<object>(null);
};
var router = new TestRouter(isHandled);
var middleware = new RouterMiddleware(next, loggerFactory, router);
// Act
await middleware.Invoke(httpContext);
// Assert
Assert.Empty(sink.Scopes);
Assert.Single(sink.Writes);
Assert.Equal(expectedMessage, sink.Writes[0].State?.ToString());
}
public async void Invoke_DoesNotLog_WhenHandled()
{
// Arrange
var isHandled = true;
var sink = new TestSink(
TestSink.EnableWithTypeName<RouterMiddleware>,
TestSink.EnableWithTypeName<RouterMiddleware>);
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var httpContext = new DefaultHttpContext();
httpContext.RequestServices = new ServiceProvider();
RequestDelegate next = (c) =>
{
return Task.FromResult<object>(null);
};
var router = new TestRouter(isHandled);
var middleware = new RouterMiddleware(next, loggerFactory, router);
// Act
await middleware.Invoke(httpContext);
// Assert
Assert.Empty(sink.Scopes);
Assert.Empty(sink.Writes);
}
public async void AttributeRoute_RouteAsyncNotHandled_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
var entry = CreateMatchingEntry("api/Store");
var route = CreateRoutingAttributeRoute(loggerFactory, entry);
var context = CreateRouteContext("/");
// Act
await route.RouteAsync(context);
// Assert
Assert.Equal(1, sink.Scopes.Count);
var scope = sink.Scopes[0];
Assert.Equal(typeof(AttributeRoute).FullName, scope.LoggerName);
Assert.Equal("AttributeRoute.RouteAsync", scope.Scope);
// There is a record for IsEnabled and one for WriteCore.
Assert.Equal(2, sink.Writes.Count);
var enabled = sink.Writes[0];
Assert.Equal(typeof(AttributeRoute).FullName, enabled.LoggerName);
Assert.Equal("AttributeRoute.RouteAsync", enabled.Scope);
Assert.Null(enabled.State);
var write = sink.Writes[1];
Assert.Equal(typeof(AttributeRoute).FullName, write.LoggerName);
Assert.Equal("AttributeRoute.RouteAsync", write.Scope);
var values = Assert.IsType<AttributeRouteRouteAsyncValues>(write.State);
Assert.Equal("AttributeRoute.RouteAsync", values.Name);
Assert.Equal(false, values.Handled);
}
private async Task<Tuple<TestSink, RouteContext>> SetUp(
bool loggerEnabled,
string routeName,
string template,
string requestPath,
TestSink testSink = null)
{
if (testSink == null)
{
testSink = new TestSink(
TestSink.EnableWithTypeName<TemplateRoute>,
TestSink.EnableWithTypeName<TemplateRoute>);
}
var loggerFactory = new TestLoggerFactory(testSink, loggerEnabled);
TemplateRoute route;
if (!string.IsNullOrEmpty(routeName))
{
route = CreateRoute(routeName, template);
}
else
{
route = CreateRoute(template);
}
var context = CreateRouteContext(requestPath, loggerFactory);
// Act
await route.RouteAsync(context);
return Tuple.Create(testSink, context);
}
public async Task RouteHandler_Success_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var displayName = "A.B.C";
var actionDescriptor = new Mock<ActionDescriptor>();
actionDescriptor
.SetupGet(ad => ad.DisplayName)
.Returns(displayName);
var context = CreateRouteContext(actionDescriptor: actionDescriptor.Object, loggerFactory: loggerFactory);
var handler = new MvcRouteHandler();
await handler.RouteAsync(context);
// Act
await context.Handler(context.HttpContext);
// Assert
Assert.Single(sink.Scopes);
Assert.Equal(displayName, sink.Scopes[0].Scope?.ToString());
Assert.Equal(2, sink.Writes.Count);
Assert.Equal($"Executing action {displayName}", sink.Writes[0].State?.ToString());
// This message has the execution time embedded, which we don't want to verify.
Assert.StartsWith($"Executed action {displayName} ", sink.Writes[1].State?.ToString());
}
public void Initialize()
{
LogConfiguration configuration = new LogConfiguration();
_sink = new TestSink();
configuration.Sinks.Add(_sink);
_kernel = new LogKernel(configuration);
}
public async Task RouteAsync_Success_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
var context = CreateRouteContext(loggerFactory: loggerFactory);
var handler = new MvcRouteHandler();
// Act
await handler.RouteAsync(context);
// Assert
var scope = Assert.Single(sink.Scopes);
Assert.Equal(typeof(MvcRouteHandler).FullName, scope.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", scope.Scope);
var write = Assert.Single(sink.Writes);
Assert.Equal(typeof(MvcRouteHandler).FullName, write.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", write.Scope);
var values = Assert.IsType<MvcRouteHandlerRouteAsyncValues>(write.State);
Assert.Equal("MvcRouteHandler.RouteAsync", values.Name);
Assert.True(values.ActionSelected);
Assert.True(values.ActionInvoked);
Assert.True(values.Handled);
}
public void LogMessage()
{
// Arrange
var controller = "home";
var action = "index";
var testSink = new TestSink();
var testLogger = new TestLogger("testlogger", testSink, enabled: true);
// Act
testLogger.ActionMatched(controller, action);
// Assert
Assert.Equal(1, testSink.Writes.Count);
var writeContext = testSink.Writes.First();
var actualLogValues = Assert.IsAssignableFrom<ILogValues>(writeContext.State);
AssertLogValues(
new[] {
new KeyValuePair<string, object>("{OriginalFormat}", TestLoggerExtensions.ActionMatchedInfo.NamedStringFormat),
new KeyValuePair<string, object>("controller", controller),
new KeyValuePair<string, object>("action", action)
},
actualLogValues.GetValues());
Assert.Equal(LogLevel.Information, writeContext.LogLevel);
Assert.Equal(1, writeContext.EventId);
Assert.Null(writeContext.Exception);
Assert.Equal(
string.Format(
TestLoggerExtensions.ActionMatchedInfo.FormatString,
controller,
action),
actualLogValues.ToString());
}
public void LogScope_WithOneParameter()
{
// Arrange
var param1 = Guid.NewGuid().ToString();
var testSink = new TestSink();
var testLogger = new TestLogger("testlogger", testSink, enabled: true);
// Act
var disposable = testLogger.ScopeWithOneParam(param1);
// Assert
Assert.NotNull(disposable);
Assert.Equal(0, testSink.Writes.Count);
Assert.Equal(1, testSink.Scopes.Count);
var scopeContext = testSink.Scopes.First();
var actualLogValues = Assert.IsAssignableFrom<ILogValues>(scopeContext.Scope);
AssertLogValues(new[]
{
new KeyValuePair<string, object>("RequestId", param1),
new KeyValuePair<string, object>("{OriginalFormat}", TestLoggerExtensions.ScopeWithOneParameter.NamedStringFormat)
},
actualLogValues.GetValues());
Assert.Equal(
string.Format(TestLoggerExtensions.ScopeWithOneParameter.FormatString, param1),
actualLogValues.ToString());
}
public async Task RouteAsync_FailOnNoAction_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var mockActionSelector = new Mock<IActionSelector>();
mockActionSelector
.Setup(a => a.Select(It.IsAny<RouteContext>()))
.Returns<ActionDescriptor>(null);
var context = CreateRouteContext(
actionSelector: mockActionSelector.Object,
loggerFactory: loggerFactory);
var handler = new MvcRouteHandler();
var expectedMessage = "No actions matched the current request";
// Act
await handler.RouteAsync(context);
// Assert
Assert.Empty(sink.Scopes);
Assert.Single(sink.Writes);
Assert.Equal(expectedMessage, sink.Writes[0].State?.ToString());
}
public async void SelectAsync_AmbiguousActions_LogIsCorrect()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var actions = new ActionDescriptor[]
{
new ActionDescriptor() { DisplayName = "A1" },
new ActionDescriptor() { DisplayName = "A2" },
};
var selector = CreateSelector(actions, loggerFactory);
var routeContext = CreateRouteContext("POST");
var actionNames = string.Join(Environment.NewLine, actions.Select(action => action.DisplayName));
var expectedMessage = "Request matched multiple actions resulting in " +
$"ambiguity. Matching actions: {actionNames}";
// Act
await Assert.ThrowsAsync<AmbiguousActionException>(async () =>
{
await selector.SelectAsync(routeContext);
});
// Assert
Assert.Empty(sink.Scopes);
Assert.Single(sink.Writes);
Assert.Equal(expectedMessage, sink.Writes[0].State?.ToString());
}
public async void SelectAsync_NoMatchedActions_LogIsCorrect()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
var routeContext = CreateRouteContext("POST");
var actions = new ActionDescriptor[0];
var selector = CreateSelector(actions, loggerFactory);
// Act
var action = await selector.SelectAsync(routeContext);
// Assert
Assert.Equal(1, sink.Scopes.Count);
var scope = sink.Scopes[0];
Assert.Equal(typeof(DefaultActionSelector).FullName, scope.LoggerName);
Assert.Equal("DefaultActionSelector.SelectAsync", scope.Scope);
Assert.Equal(1, sink.Writes.Count);
var write = sink.Writes[0];
Assert.Equal(typeof(DefaultActionSelector).FullName, write.LoggerName);
Assert.Equal("DefaultActionSelector.SelectAsync", write.Scope);
var values = Assert.IsType<DefaultActionSelectorSelectAsyncValues>(write.State);
Assert.Equal("DefaultActionSelector.SelectAsync", values.Name);
Assert.Empty(values.ActionsMatchingRouteConstraints);
Assert.Empty(values.ActionsMatchingActionConstraints);
Assert.Empty(values.FinalMatches);
Assert.Null(values.SelectedAction);
// (does not throw)
Assert.NotEmpty(values.Summary);
}
public void ManualTest()
{
var infoSink = new TestSink();
var debugSink = new TestSink();
Logger.Setup(configuration =>
{
configuration
.WriteTo.Sink(debugSink)
.WriteTo.Sink(infoSink, restrictedToMinimumLevel: LogEventLevel.Information);
return configuration;
});
Logger.Instance.Debug("debug 1");
Logger.Instance.Debug("debug 2: {Message}", "foo");
Logger.Instance.Information("info 1");
Logger.Instance.Information("info 2: {AnotherMessage:l}", "bar");
var logger = Logger.Instance.ForContext<LoggerTests>();
logger.Debug("debug 3");
logger.Information("info 3");
Assert.Equal(6, debugSink.Events.Count);
Assert.Equal(3, infoSink.Events.Count);
Assert.Contains("debug 2: \"foo\"", debugSink.Events.Select(e => e.RenderMessage()));
Assert.Contains("info 2: bar", debugSink.Events.Select(e => e.RenderMessage()));
}
public void AsyncProxy_LogEntriesAreWrittenToSinks()
{
LogConfiguration configuration = new LogConfiguration();
AsyncProxy asyncProxy = new AsyncProxy();
ManualResetEvent stoppedEvent = new ManualResetEvent(false);
TestSink sink = new TestSink(stoppedEvent);
asyncProxy.Sinks.Add(sink);
configuration.Sinks.Add(asyncProxy);
using (LogKernel kernel = new LogKernel(configuration))
{
ILogger logger = kernel.GetLogger();
logger.Write(LogLevel.Information, "A message");
// Wait for the entry to be written.
if (!stoppedEvent.WaitOne(TimeSpan.FromSeconds(3)))
{
throw new TimeoutException("Timed out while waiting for entries to be written to sink.");
}
// Assert that the entry was written to the sink.
Assert.IsNotNull(sink.Entry);
Assert.AreEqual("A message", sink.Entry.Message);
Assert.AreEqual(1, sink.WrittenEntries);
}
}
public async void Invoke_DoesNotLogWhenDisabledAndNotHandled()
{
// Arrange
var isHandled = false;
var sink = new TestSink(
TestSink.EnableWithTypeName<RouterMiddleware>,
TestSink.EnableWithTypeName<RouterMiddleware>);
var loggerFactory = new TestLoggerFactory(sink, enabled: false);
var httpContext = new DefaultHttpContext();
httpContext.ApplicationServices = new ServiceProvider();
httpContext.RequestServices = httpContext.ApplicationServices;
RequestDelegate next = (c) =>
{
return Task.FromResult<object>(null);
};
var router = new TestRouter(isHandled);
var middleware = new RouterMiddleware(next, loggerFactory, router);
// Act
await middleware.Invoke(httpContext);
// Assert
Assert.Single(sink.Scopes);
var scope = sink.Scopes[0];
Assert.Equal(typeof(RouterMiddleware).FullName, scope.LoggerName);
Assert.Equal("RouterMiddleware.Invoke", scope.Scope);
Assert.Empty(sink.Writes);
}
public void FormatMessage_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var logger = SetUp(sink);
// Act
logger.LogVerbose(_format, "test1", "test2");
logger.LogInformation(_format, "test1", "test2");
logger.LogWarning(_format, "test1", "test2");
logger.LogError(_format, "test1", "test2");
logger.LogCritical(_format, "test1", "test2");
logger.LogDebug(_format, "test1", "test2");
// Assert
Assert.Equal(6, sink.Writes.Count);
var verbose = sink.Writes[0];
Assert.Equal(LogLevel.Verbose, verbose.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), verbose.State?.ToString());
Assert.Equal(0, verbose.EventId);
Assert.Equal(null, verbose.Exception);
var information = sink.Writes[1];
Assert.Equal(LogLevel.Information, information.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), information.State?.ToString());
Assert.Equal(0, information.EventId);
Assert.Equal(null, information.Exception);
var warning = sink.Writes[2];
Assert.Equal(LogLevel.Warning, warning.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), warning.State?.ToString());
Assert.Equal(0, warning.EventId);
Assert.Equal(null, warning.Exception);
var error = sink.Writes[3];
Assert.Equal(LogLevel.Error, error.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), error.State?.ToString());
Assert.Equal(0, error.EventId);
Assert.Equal(null, error.Exception);
var critical = sink.Writes[4];
Assert.Equal(LogLevel.Critical, critical.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), critical.State?.ToString());
Assert.Equal(0, critical.EventId);
Assert.Equal(null, critical.Exception);
var debug = sink.Writes[5];
Assert.Equal(LogLevel.Debug, debug.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), debug.State?.ToString());
Assert.Equal(0, debug.EventId);
Assert.Equal(null, debug.Exception);
}
public void FormatMessageAndEventId_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var logger = SetUp(sink);
// Act
logger.LogVerbose(1, _format, "test1", "test2");
logger.LogInformation(2, _format, "test1", "test2");
logger.LogWarning(3, _format, "test1", "test2");
logger.LogError(4, _format, "test1", "test2");
logger.LogCritical(5, _format, "test1", "test2");
logger.LogDebug(6, _format, "test1", "test2");
// Assert
Assert.Equal(6, sink.Writes.Count);
var verbose = sink.Writes[0];
Assert.Equal(LogLevel.Verbose, verbose.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), ((ILogValues)verbose.State).Format());
Assert.Equal(1, verbose.EventId);
Assert.Equal(null, verbose.Exception);
var information = sink.Writes[1];
Assert.Equal(LogLevel.Information, information.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), ((ILogValues)information.State).Format());
Assert.Equal(2, information.EventId);
Assert.Equal(null, information.Exception);
var warning = sink.Writes[2];
Assert.Equal(LogLevel.Warning, warning.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), ((ILogValues)warning.State).Format());
Assert.Equal(3, warning.EventId);
Assert.Equal(null, warning.Exception);
var error = sink.Writes[3];
Assert.Equal(LogLevel.Error, error.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), ((ILogValues)error.State).Format());
Assert.Equal(4, error.EventId);
Assert.Equal(null, error.Exception);
var critical = sink.Writes[4];
Assert.Equal(LogLevel.Critical, critical.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), ((ILogValues)critical.State).Format());
Assert.Equal(5, critical.EventId);
Assert.Equal(null, critical.Exception);
var debug = sink.Writes[5];
Assert.Equal(LogLevel.Debug, debug.LogLevel);
Assert.Equal(string.Format(_format, "test1", "test2"), ((ILogValues)debug.State).Format());
Assert.Equal(6, debug.EventId);
Assert.Equal(null, debug.Exception);
}
public async void SelectAsync_MatchedActions_LogIsCorrect()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
var matched = new ActionDescriptor()
{
MethodConstraints = new List<HttpMethodConstraint>()
{
new HttpMethodConstraint(new string[] { "POST" }),
},
Parameters = new List<ParameterDescriptor>(),
};
var notMatched = new ActionDescriptor()
{
Parameters = new List<ParameterDescriptor>(),
};
var actions = new ActionDescriptor[] { matched, notMatched };
var selector = CreateSelector(actions, loggerFactory);
var routeContext = CreateRouteContext("POST");
// Act
var action = await selector.SelectAsync(routeContext);
// Assert
Assert.Equal(1, sink.Scopes.Count);
var scope = sink.Scopes[0];
Assert.Equal(typeof(DefaultActionSelector).FullName, scope.LoggerName);
Assert.Equal("DefaultActionSelector.SelectAsync", scope.Scope);
// There is a record for IsEnabled and one for WriteCore.
Assert.Equal(2, sink.Writes.Count);
var enabled = sink.Writes[0];
Assert.Equal(typeof(DefaultActionSelector).FullName, enabled.LoggerName);
Assert.Equal("DefaultActionSelector.SelectAsync", enabled.Scope);
Assert.Null(enabled.State);
var write = sink.Writes[1];
Assert.Equal(typeof(DefaultActionSelector).FullName, write.LoggerName);
Assert.Equal("DefaultActionSelector.SelectAsync", write.Scope);
var values = Assert.IsType<DefaultActionSelectorSelectAsyncValues>(write.State);
Assert.Equal("DefaultActionSelector.SelectAsync", values.Name);
Assert.NotEmpty(values.ActionsMatchingRouteConstraints);
Assert.NotEmpty(values.ActionsMatchingRouteAndMethodConstraints);
Assert.NotEmpty(values.ActionsMatchingWithConstraints);
Assert.Equal(matched, values.SelectedAction);
}
private async Task<Tuple<TestSink, RouteContext>> SetUp(bool enabled, string template, string requestPath)
{
var sink = new TestSink(
TestSink.EnableWithTypeName<TemplateRoute>,
TestSink.EnableWithTypeName<TemplateRoute>);
var loggerFactory = new TestLoggerFactory(sink, enabled);
var route = CreateRoute(template);
var context = CreateRouteContext(requestPath, loggerFactory);
// Act
await route.RouteAsync(context);
return Tuple.Create(sink, context);
}
public void ActionDiscovery()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
// Act
CreateActionDescriptors(loggerFactory,
typeof(SimpleController).GetTypeInfo(),
typeof(BasicController).GetTypeInfo());
// Assert
// 2 controllers, 3 actions
Assert.Equal(5, sink.Writes.Count);
Assert.IsType<ControllerModelValues>(sink.Writes[0].State);
Assert.IsType<ControllerModelValues>(sink.Writes[1].State);
var actionDescriptorValues = Assert.IsType<ActionDescriptorValues>(sink.Writes[2].State);
Assert.NotNull(actionDescriptorValues);
Assert.Equal("EmptyAction", actionDescriptorValues.Name);
Assert.Equal("Simple", actionDescriptorValues.ControllerName);
Assert.Equal(typeof(SimpleController), actionDescriptorValues.ControllerTypeInfo);
Assert.Null(actionDescriptorValues.AttributeRouteInfo.Name);
Assert.Null(actionDescriptorValues.ActionConstraints);
Assert.Empty(actionDescriptorValues.FilterDescriptors);
Assert.Empty(actionDescriptorValues.Parameters);
actionDescriptorValues = Assert.IsType<ActionDescriptorValues>(sink.Writes[3].State);
Assert.NotNull(actionDescriptorValues);
Assert.Equal("Basic", actionDescriptorValues.Name);
Assert.Equal("Basic", actionDescriptorValues.ControllerName);
Assert.Equal(typeof(BasicController), actionDescriptorValues.ControllerTypeInfo);
Assert.Null(actionDescriptorValues.AttributeRouteInfo.Name);
Assert.NotEmpty(actionDescriptorValues.ActionConstraints);
Assert.Equal(2, actionDescriptorValues.FilterDescriptors.Count);
Assert.Empty(actionDescriptorValues.Parameters);
actionDescriptorValues = Assert.IsType<ActionDescriptorValues>(sink.Writes[4].State);
Assert.NotNull(actionDescriptorValues);
Assert.Equal("Basic", actionDescriptorValues.Name);
Assert.Equal("Basic", actionDescriptorValues.ControllerName);
Assert.Equal(typeof(BasicController), actionDescriptorValues.ControllerTypeInfo);
Assert.Null(actionDescriptorValues.AttributeRouteInfo.Name);
Assert.NotEmpty(actionDescriptorValues.ActionConstraints);
Assert.Single(actionDescriptorValues.FilterDescriptors);
Assert.Single(actionDescriptorValues.RouteConstraints);
Assert.Single(actionDescriptorValues.Parameters);
}
public async void SelectAsync_MatchedActions_LogIsCorrect()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
var matched = new ActionDescriptor()
{
ActionConstraints = new List<IActionConstraintMetadata>()
{
new HttpMethodConstraint(new string[] { "POST" }),
},
Parameters = new List<ParameterDescriptor>(),
};
var notMatched = new ActionDescriptor()
{
Parameters = new List<ParameterDescriptor>(),
};
var actions = new ActionDescriptor[] { matched, notMatched };
var selector = CreateSelector(actions, loggerFactory);
var routeContext = CreateRouteContext("POST");
// Act
var action = await selector.SelectAsync(routeContext);
// Assert
Assert.Equal(1, sink.Scopes.Count);
var scope = sink.Scopes[0];
Assert.Equal(typeof(DefaultActionSelector).FullName, scope.LoggerName);
Assert.Equal("DefaultActionSelector.SelectAsync", scope.Scope);
Assert.Equal(1, sink.Writes.Count);
var write = sink.Writes[0];
Assert.Equal(typeof(DefaultActionSelector).FullName, write.LoggerName);
Assert.Equal("DefaultActionSelector.SelectAsync", write.Scope);
var values = Assert.IsType<DefaultActionSelectorSelectAsyncValues>(write.State);
Assert.Equal("DefaultActionSelector.SelectAsync", values.Name);
Assert.Equal<ActionDescriptor>(actions, values.ActionsMatchingRouteConstraints);
Assert.Equal<ActionDescriptor>(new[] { matched }, values.ActionsMatchingActionConstraints);
Assert.Equal(matched, Assert.Single(values.FinalMatches));
Assert.Equal(matched, values.SelectedAction);
}
public void BufferProxy_RemainingMessagesAreFlushedWhenBufferProxyIsDisposed()
{
LogConfiguration configuration = new LogConfiguration();
BufferProxy proxy = new BufferProxy { BufferSize = 3 };
TestSink sink = new TestSink();
proxy.Sinks.Add(sink);
configuration.Sinks.Add(proxy);
LogKernel kernel = new LogKernel(configuration);
ILogger logger = kernel.GetLogger();
Assert.AreEqual(0, sink.MessagesWritten);
logger.Write(LogLevel.Information, "Hello World!");
logger.Write(LogLevel.Information, "Hello World Again!");
Assert.AreEqual(0, sink.MessagesWritten);
configuration.Dispose();
Assert.AreEqual(2, sink.MessagesWritten);
}
public async void RouteAsync_FailOnNoAction_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
var mockActionSelector = new Mock<IActionSelector>();
mockActionSelector.Setup(a => a.SelectAsync(It.IsAny<RouteContext>()))
.Returns(Task.FromResult<ActionDescriptor>(null));
var context = CreateRouteContext(
actionSelector: mockActionSelector.Object,
loggerFactory: loggerFactory);
var handler = new MvcRouteHandler();
// Act
await handler.RouteAsync(context);
// Assert
Assert.Equal(1, sink.Scopes.Count);
var scope = sink.Scopes[0];
Assert.Equal(typeof(MvcRouteHandler).FullName, scope.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", scope.Scope);
// There is a record for IsEnabled and one for WriteCore.
Assert.Equal(2, sink.Writes.Count);
var enabled = sink.Writes[0];
Assert.Equal(typeof(MvcRouteHandler).FullName, enabled.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", enabled.Scope);
Assert.Null(enabled.State);
var write = sink.Writes[1];
Assert.Equal(typeof(MvcRouteHandler).FullName, write.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", write.Scope);
var values = Assert.IsType<MvcRouteHandlerRouteAsyncValues>(write.State);
Assert.Equal("MvcRouteHandler.RouteAsync", values.Name);
Assert.Equal(false, values.ActionSelected);
Assert.Equal(false, values.ActionInvoked);
Assert.Equal(false, values.Handled);
}
private void CreateDefaultConfiguration()
{
Client = new BlazorClient()
{
DefaultLatencyTimeout = DefaultLatencyTimeout
};
Client.RenderBatchReceived += (id, data) => Batches.Add(new Batch(id, data));
Client.DotNetInteropCompletion += (method) => DotNetCompletions.Add(new DotNetCompletion(method));
Client.JSInterop += (asyncHandle, identifier, argsJson) => JSInteropCalls.Add(new JSInteropCall(asyncHandle, identifier, argsJson));
Client.OnCircuitError += (error) => Errors.Add(error);
Client.LoggerProvider = new XunitLoggerProvider(Output);
Client.FormatError = (error) =>
{
var logs = string.Join(Environment.NewLine, Logs);
return(new Exception(error + Environment.NewLine + logs));
};
_ = _serverFixture.RootUri; // this is needed for the side-effects of getting the URI.
TestSink = _serverFixture.Host.Services.GetRequiredService <TestSink>();
TestSink.MessageLogged += LogMessages;
}
public void ParsePathByAddresss_HasMatches_ReturnsNullWhenParsingFails()
{
// Arrange
var endpoint1 = EndpointFactory.CreateRouteEndpoint("{controller}/{action}/{id}", displayName: "Test1", metadata: new object[] { new IntMetadata(1), });
var endpoint2 = EndpointFactory.CreateRouteEndpoint("{controller}/{action}/{id2}", displayName: "Test2", metadata: new object[] { new IntMetadata(0), });
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var parser = CreateLinkParser(services => { services.AddSingleton <ILoggerFactory>(loggerFactory); }, endpoint1, endpoint2);
// Act
var values = parser.ParsePathByAddress(0, "/");
// Assert
Assert.Null(values);
Assert.Collection(
sink.Writes,
w => Assert.Equal("Found the endpoints Test2 for address 0", w.Message),
w => Assert.Equal("Path parsing failed for endpoints Test2 and URI path /", w.Message));
}
public void EvaluatePolicy_LoggingForPreflightRequests_HasOriginHeader_PolicySucceeded()
{
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var corsService = new CorsService(new TestCorsOptions(), loggerFactory);
var requestContext = GetHttpContext(method: "OPTIONS", origin: "http://allowed.example.com", accessControlRequestMethod: "PUT");
var policy = new CorsPolicy();
policy.Origins.Add("http://allowed.example.com");
policy.Methods.Add("PUT");
// Act
var result = corsService.EvaluatePolicy(requestContext, policy);
var writeList = sink.Writes.ToList();
Assert.Equal("The request is a preflight request.", writeList[0].State.ToString());
Assert.Equal("The request has an origin header: 'http://allowed.example.com'.", writeList[1].State.ToString());
Assert.Equal("Policy execution successful.", writeList[2].State.ToString());
}
public void Deadline_TooLong_LoggedAndMaximumDeadlineUsed()
{
// Arrange
var testSink = new TestSink();
var testLogger = new TestLogger(string.Empty, testSink, true);
var httpContext = new DefaultHttpContext();
httpContext.Request.Headers[GrpcProtocolConstants.TimeoutHeader] = "9999999H";
var context = CreateServerCallContext(httpContext, testLogger);
// Act
context.Initialize(TestClock);
// Assert
Assert.AreEqual(TestClock.UtcNow.Add(TimeSpan.FromTicks(GrpcProtocolConstants.MaxDeadlineTicks)), context.Deadline);
var write = testSink.Writes.Single(w => w.EventId.Name == "DeadlineTimeoutTooLong");
Assert.AreEqual("Deadline timeout 416666.15:00:00 is above maximum allowed timeout of 99999999 seconds. Maximum timeout will be used.", write.State.ToString());
}
public void IsCachedEntryFresh_RequestMaxAgeRestrictAge_ToNotFresh()
{
var sink = new TestSink();
var context = TestUtils.CreateTestContext(sink);
context.HttpContext.Request.Headers.CacheControl = new CacheControlHeaderValue()
{
MaxAge = TimeSpan.FromSeconds(5)
}.ToString();
context.CachedResponseHeaders = new HeaderDictionary();
context.CachedResponseHeaders[HeaderNames.CacheControl] = new CacheControlHeaderValue()
{
MaxAge = TimeSpan.FromSeconds(10),
}.ToString();
context.CachedEntryAge = TimeSpan.FromSeconds(5);
Assert.False(new ResponseCachingPolicyProvider().IsCachedEntryFresh(context));
TestUtils.AssertLoggedMessages(
sink.Writes,
LoggedMessage.ExpirationMaxAgeExceeded);
}
public void IsCachedEntryFresh_MaxAgeOverridesExpiry_ToNotFresh()
{
var utcNow = DateTimeOffset.UtcNow;
var sink = new TestSink();
var context = TestUtils.CreateTestContext(sink);
context.CachedEntryAge = TimeSpan.FromSeconds(10);
context.ResponseTime = utcNow + context.CachedEntryAge;
context.CachedResponseHeaders = new HeaderDictionary();
context.CachedResponseHeaders[HeaderNames.CacheControl] = new CacheControlHeaderValue()
{
Public = true,
MaxAge = TimeSpan.FromSeconds(10)
}.ToString();
context.HttpContext.Response.Headers.Expires = HeaderUtilities.FormatDate(utcNow);
Assert.False(new ResponseCachingPolicyProvider().IsCachedEntryFresh(context));
TestUtils.AssertLoggedMessages(
sink.Writes,
LoggedMessage.ExpirationMaxAgeExceeded);
}
public async Task FinalizeCacheHeadersAsync_ResponseValidity_UseExpiryIfAvailable()
{
var clock = new TestClock
{
UtcNow = DateTimeOffset.MinValue
};
var sink = new TestSink();
var middleware = TestUtils.CreateTestMiddleware(testSink: sink, options: new ResponseCachingOptions
{
SystemClock = clock
});
var context = TestUtils.CreateTestContext();
context.ResponseTime = clock.UtcNow;
context.HttpContext.Response.Headers[HeaderNames.Expires] = HeaderUtilities.FormatDate(clock.UtcNow + TimeSpan.FromSeconds(11));
await middleware.FinalizeCacheHeadersAsync(context);
Assert.Equal(TimeSpan.FromSeconds(11), context.CachedResponseValidFor);
Assert.Empty(sink.Writes);
}
public void LogsMaxRequestBodySizeSetToNull()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var disableRequestSizeLimitResourceFilter = new DisableRequestSizeLimitFilter(loggerFactory);
var authorizationFilterContext = CreateAuthorizationFilterContext(new IFilterMetadata[] { disableRequestSizeLimitResourceFilter });
var httpMaxRequestBodySize = new TestHttpMaxRequestBodySizeFeature();
authorizationFilterContext.HttpContext.Features.Set <IHttpMaxRequestBodySizeFeature>(httpMaxRequestBodySize);
// Act
disableRequestSizeLimitResourceFilter.OnAuthorization(authorizationFilterContext);
// Assert
var write = Assert.Single(sink.Writes);
Assert.Equal($"The request body size limit has been disabled.", write.State.ToString());
}
public void Deadline_ParseInvalidHeader_IgnoresHeader(string header)
{
// Arrange
var testSink = new TestSink();
var testLogger = new TestLogger(string.Empty, testSink, true);
var httpContext = new DefaultHttpContext();
httpContext.Request.Headers[GrpcProtocolConstants.TimeoutHeader] = header;
var context = CreateServerCallContext(httpContext, testLogger);
// Act
context.Initialize();
// Assert
Assert.AreEqual(DateTime.MaxValue, context.Deadline);
var write = testSink.Writes.Single(w => w.EventId.Name == "InvalidTimeoutIgnored");
Assert.AreEqual($"Invalid grpc-timeout header value '{header}' has been ignored.", write.State.ToString());
}
public void IsResponseCacheable_SharedMaxAgeOverridesMaxAge_ToNotAllowed()
{
var utcNow = DateTimeOffset.UtcNow;
var sink = new TestSink();
var context = TestUtils.CreateTestContext(sink);
context.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
context.HttpContext.Response.Headers.CacheControl = new CacheControlHeaderValue()
{
Public = true,
MaxAge = TimeSpan.FromSeconds(10),
SharedMaxAge = TimeSpan.FromSeconds(5)
}.ToString();
context.HttpContext.Response.Headers.Date = HeaderUtilities.FormatDate(utcNow);
context.ResponseTime = utcNow + TimeSpan.FromSeconds(5);
Assert.False(new ResponseCachingPolicyProvider().IsResponseCacheable(context));
TestUtils.AssertLoggedMessages(
sink.Writes,
LoggedMessage.ExpirationSharedMaxAgeExceeded);
}
public async Task SessionStart_LogsInformation()
{
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var builder = new WebHostBuilder()
.Configure(app =>
{
app.UseSession();
app.Run(context =>
{
context.Session.SetString("Key", "Value");
return(Task.FromResult(0));
});
})
.ConfigureServices(services =>
{
services.AddSingleton(typeof(ILoggerFactory), loggerFactory);
services.AddMemoryCache();
services.AddDistributedMemoryCache();
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.OnlyMessagesFromSource <DistributedSession>().ToArray();
Assert.Equal(2, sessionLogMessages.Length);
Assert.Contains("started", sessionLogMessages[0].State.ToString());
Assert.Equal(LogLevel.Information, sessionLogMessages[0].LogLevel);
Assert.Contains("stored", sessionLogMessages[1].State.ToString());
Assert.Equal(LogLevel.Debug, sessionLogMessages[1].LogLevel);
}
}
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);
}
public async Task SessionLogsCacheRefreshException()
{
var sink = new TestSink(
TestSink.EnableWithTypeName <SessionMiddleware>,
TestSink.EnableWithTypeName <SessionMiddleware>);
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var builder = new WebHostBuilder()
.Configure(app =>
{
app.UseSession();
app.Run(context =>
{
// The middleware calls context.Session.CommitAsync() once per request
return(Task.FromResult(0));
});
})
.ConfigureServices(services =>
{
services.AddSingleton(typeof(ILoggerFactory), loggerFactory);
services.AddSingleton <IDistributedCache>(new UnreliableCache(new MemoryCache(new MemoryCacheOptions()))
{
DisableRefreshAsync = 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.Equal(1, sessionLogMessages.Count);
Assert.Contains("Error closing the session.", sessionLogMessages[0].State.ToString());
Assert.Equal(LogLevel.Error, sessionLogMessages[0].LogLevel);
}
public void LogsFilters_OnlyWhenLogger_IsEnabled()
{
// Arrange
var authFilter = Mock.Of <IAuthorizationFilter>();
var asyncAuthFilter = Mock.Of <IAsyncAuthorizationFilter>();
var actionFilter = Mock.Of <IActionFilter>();
var asyncActionFilter = Mock.Of <IAsyncActionFilter>();
var exceptionFilter = Mock.Of <IExceptionFilter>();
var asyncExceptionFilter = Mock.Of <IAsyncExceptionFilter>();
var resultFilter = Mock.Of <IResultFilter>();
var asyncResultFilter = Mock.Of <IAsyncResultFilter>();
var resourceFilter = Mock.Of <IResourceFilter>();
var asyncResourceFilter = Mock.Of <IAsyncResourceFilter>();
var filters = new IFilterMetadata[]
{
actionFilter,
asyncActionFilter,
authFilter,
asyncAuthFilter,
exceptionFilter,
asyncExceptionFilter,
resultFilter,
asyncResultFilter,
resourceFilter,
asyncResourceFilter
};
var testSink = new TestSink();
var loggerFactory = new TestLoggerFactory(testSink, enabled: false);
var logger = loggerFactory.CreateLogger("test");
// Act
logger.AuthorizationFiltersExecutionPlan(filters);
logger.ResourceFiltersExecutionPlan(filters);
logger.ActionFiltersExecutionPlan(filters);
logger.ExceptionFiltersExecutionPlan(filters);
logger.ResultFiltersExecutionPlan(filters);
// Assert
Assert.Empty(testSink.Writes);
}
public async Task AsyncUnaryCall_Success_LogToFactory()
{
// Arrange
var httpClient = TestHelpers.CreateTestClient(async request =>
{
// Trigger request stream serialization
await request.Content.ReadAsStreamAsync().DefaultTimeout();
var streamContent = await TestHelpers.CreateResponseContent(new HelloReply
{
Message = "Hello world"
}).DefaultTimeout();
return(ResponseUtils.CreateResponse(HttpStatusCode.OK, streamContent));
});
var testSink = new TestSink();
var loggerFactory = new TestLoggerFactory(testSink, true);
var invoker = HttpClientCallInvokerFactory.Create(httpClient, loggerFactory);
// Act
var rs = await invoker.AsyncUnaryCall <HelloRequest, HelloReply>(TestHelpers.ServiceMethod, string.Empty, new CallOptions(), new HelloRequest());
// Assert
Assert.AreEqual("Hello world", rs.Message);
var logs = testSink.Writes.Where(w => w.LogLevel >= Microsoft.Extensions.Logging.LogLevel.Debug).ToList();
Assert.AreEqual("Starting gRPC call. Method type: 'Unary', URI: '/ServiceName/MethodName'.", logs[0].State.ToString());
AssertScope(logs[0]);
Assert.AreEqual("Sending message.", logs[1].State.ToString());
AssertScope(logs[1]);
Assert.AreEqual("Reading message.", logs[2].State.ToString());
AssertScope(logs[2]);
Assert.AreEqual("Finished gRPC call.", logs[3].State.ToString());
AssertScope(logs[3]);
public void EvaluatePolicy_LoggingForPreflightRequests_HasOriginHeader_PolicyFailed(LogData logData)
{
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var corsService = new CorsService(new TestCorsOptions(), loggerFactory);
var requestContext = GetHttpContext(method: "OPTIONS", origin: logData.Origin, accessControlRequestMethod: logData.Method, accessControlRequestHeaders: logData.Headers);
var policy = new CorsPolicy();
policy.Origins.Add("http://allowed.example.com");
policy.Methods.Add("PUT");
// Act
var result = corsService.EvaluatePolicy(requestContext, policy);
var writeList = sink.Writes.ToList();
Assert.Equal("The request is a preflight request.", writeList[0].State.ToString());
Assert.Equal(logData.OriginLogMessage, writeList[1].State.ToString());
Assert.Equal(logData.PolicyLogMessage, writeList[2].State.ToString());
Assert.Equal(logData.FailureReason, writeList[3].State.ToString());
}
public async Task AsyncClientStreamingCall_DeadlineLargerThanMaxTimerDueTime_DeadlineExceeded()
{
// Arrange
var testSink = new TestSink();
var testLoggerFactory = new TestLoggerFactory(testSink, true);
var httpClient = ClientTestHelpers.CreateTestClient(async request =>
{
var content = (PushStreamContent <HelloRequest, HelloReply>)request.Content;
await content.PushComplete.DefaultTimeout();
return(ResponseUtils.CreateResponse(HttpStatusCode.OK));
});
var testSystemClock = new TestSystemClock(DateTime.UtcNow);
var invoker = HttpClientCallInvokerFactory.Create(httpClient, systemClock: testSystemClock, maxTimerPeriod: 20, loggerFactory: testLoggerFactory);
var timeout = TimeSpan.FromSeconds(0.2);
var deadline = testSystemClock.UtcNow.Add(timeout);
// Act
var call = invoker.AsyncClientStreamingCall <HelloRequest, HelloReply>(ClientTestHelpers.ServiceMethod, string.Empty, new CallOptions(deadline: deadline));
// Assert
var responseTask = call.ResponseAsync;
await Task.Delay(timeout);
// Update time so deadline exceeds correctly
testSystemClock.UtcNow = deadline;
var ex = await ExceptionAssert.ThrowsAsync <RpcException>(() => responseTask).DefaultTimeout();
Assert.AreEqual(StatusCode.DeadlineExceeded, ex.StatusCode);
Assert.AreEqual(StatusCode.DeadlineExceeded, call.GetStatus().StatusCode);
var write = testSink.Writes.First(w => w.EventId.Name == "DeadlineTimerRescheduled");
Assert.AreEqual(LogLevel.Trace, write.LogLevel);
Assert.AreEqual("Deadline timer triggered but 00:00:00.2000000 remaining before deadline exceeded. Deadline timer rescheduled.", write.Message);
}
public async Task CancellationToken_WithDeadline_CancellationRequested()
{
// Arrange
var testSink = new TestSink();
var testLogger = new TestLogger(string.Empty, testSink, true);
var httpContext = new DefaultHttpContext();
httpContext.Features.Set <IHttpRequestLifetimeFeature>(new TestHttpRequestLifetimeFeature());
httpContext.Request.Headers[GrpcProtocolConstants.TimeoutHeader] = "1S";
var context = CreateServerCallContext(httpContext, testLogger);
context.Initialize();
// Act
try
{
await Task.WhenAll(
Task.Delay(int.MaxValue, context.CancellationToken),
Task.Delay(int.MaxValue, httpContext.RequestAborted)
).DefaultTimeout();
Assert.Fail();
}
catch (TaskCanceledException)
{
}
// Assert
Assert.IsTrue(context.CancellationToken.IsCancellationRequested);
Assert.IsTrue(httpContext.RequestAborted.IsCancellationRequested);
var write = testSink.Writes.Single(w => w.EventId.Name == "DeadlineStarted");
Assert.AreEqual("Request deadline timeout of 00:00:01 started.", write.State.ToString());
write = testSink.Writes.Single(w => w.EventId.Name == "DeadlineExceeded");
Assert.AreEqual("Request with timeout of 00:00:01 has exceeded its deadline.", write.State.ToString());
}
public async Task TryServeFromCacheAsync_CachedResponseFound_Succeeds()
{
var cache = new TestResponseCache();
var sink = new TestSink();
var middleware = TestUtils.CreateTestMiddleware(testSink: sink, cache: cache, keyProvider: new TestResponseCachingKeyProvider("BaseKey"));
var context = TestUtils.CreateTestContext();
await cache.SetAsync(
"BaseKey",
new CachedResponse()
{
Headers = new HeaderDictionary(),
Body = new SegmentReadStream(new List <byte[]>(0), 0)
},
TimeSpan.Zero);
Assert.True(await middleware.TryServeFromCacheAsync(context));
Assert.Equal(1, cache.GetCount);
TestUtils.AssertLoggedMessages(
sink.Writes,
LoggedMessage.CachedResponseServed);
}
public async Task CheckHealthAsync_SetsUpALoggerScopeForEachCheck()
{
// Arrange
var sink = new TestSink();
var check = new DelegateHealthCheck(cancellationToken =>
{
Assert.Collection(sink.Scopes,
actual =>
{
Assert.Equal(actual.LoggerName, typeof(DefaultHealthCheckService).FullName);
Assert.Collection((IEnumerable <KeyValuePair <string, object> >)actual.Scope,
item =>
{
Assert.Equal("HealthCheckName", item.Key);
Assert.Equal("TestScope", item.Value);
});
});
return(Task.FromResult(HealthCheckResult.Healthy()));
});
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var service = CreateHealthChecksService(b =>
{
// Override the logger factory for testing
b.Services.AddSingleton <ILoggerFactory>(loggerFactory);
b.AddCheck("TestScope", check);
});
// Act
var results = await service.CheckHealthAsync();
// Assert
Assert.Collection(results.Entries, actual =>
{
Assert.Equal("TestScope", actual.Key);
Assert.Equal(HealthStatus.Healthy, actual.Value.Status);
});
}
public void IsCachedEntryFresh_MaxStaleInfiniteOverridesFreshness_ToFresh()
{
var sink = new TestSink();
var context = TestUtils.CreateTestContext(sink);
context.HttpContext.Request.Headers.CacheControl = new CacheControlHeaderValue()
{
MaxAge = TimeSpan.FromSeconds(5),
MaxStale = true // No value specified means a MaxStaleLimit of infinity
}.ToString();
context.CachedResponseHeaders = new HeaderDictionary();
context.CachedResponseHeaders[HeaderNames.CacheControl] = new CacheControlHeaderValue()
{
MaxAge = TimeSpan.FromSeconds(5),
}.ToString();
context.CachedEntryAge = TimeSpan.FromSeconds(6);
Assert.True(new ResponseCachingPolicyProvider().IsCachedEntryFresh(context));
TestUtils.AssertLoggedMessages(
sink.Writes,
LoggedMessage.ExpirationInfiniteMaxStaleSatisfied);
}
public async Task RouteAsync_Success_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var displayName = "A.B.C";
var actionDescriptor = new Mock<ActionDescriptor>();
actionDescriptor.SetupGet(ad => ad.DisplayName)
.Returns(displayName);
var context = CreateRouteContext(actionDescriptor: actionDescriptor.Object, loggerFactory: loggerFactory);
var handler = new MvcRouteHandler();
var expectedMessage = $"Executing action {displayName}";
// Act
await handler.RouteAsync(context);
// Assert
Assert.Single(sink.Scopes);
Assert.StartsWith("ActionId: ", sink.Scopes[0].Scope?.ToString());
Assert.Single(sink.Writes);
Assert.Equal(expectedMessage, sink.Writes[0].State?.ToString());
}
public void ParsePathByAddresss_HasMatches_ReturnsFirstSuccessfulParse()
{
// Arrange
var endpoint0 = EndpointFactory.CreateRouteEndpoint("{controller}/{action}", displayName: "Test1", metadata: new object[] { new IntMetadata(0), });
var endpoint1 = EndpointFactory.CreateRouteEndpoint("{controller}/{action}/{id}", displayName: "Test2", metadata: new object[] { new IntMetadata(0), });
var endpoint2 = EndpointFactory.CreateRouteEndpoint("{controller}/{action}/{id2}", displayName: "Test3", metadata: new object[] { new IntMetadata(0), });
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var parser = CreateLinkParser(services => { services.AddSingleton <ILoggerFactory>(loggerFactory); }, endpoint0, endpoint1, endpoint2);
// Act
var values = parser.ParsePathByAddress(0, "/Home/Index/17");
// Assert
MatcherAssert.AssertRouteValuesEqual(new { controller = "Home", action = "Index", id = "17" }, values);
Assert.Collection(
sink.Writes,
w => Assert.Equal("Found the endpoints Test1, Test2, Test3 for address 0", w.Message),
w => Assert.Equal("Path parsing succeeded for endpoint Test2 and URI path /Home/Index/17", w.Message));
}
public void IsResponseCacheable_AtExpiry_NotAllowed()
{
var sink = new TestSink();
var context = TestUtils.CreateTestContext(sink);
context.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
context.HttpContext.Response.Headers.CacheControl = new CacheControlHeaderValue()
{
Public = true
}.ToString();
var utcNow = DateTimeOffset.UtcNow;
context.HttpContext.Response.Headers.Expires = HeaderUtilities.FormatDate(utcNow);
context.HttpContext.Response.Headers.Date = HeaderUtilities.FormatDate(utcNow);
context.ResponseTime = utcNow;
Assert.False(new ResponseCachingPolicyProvider().IsResponseCacheable(context));
TestUtils.AssertLoggedMessages(
sink.Writes,
LoggedMessage.ExpirationExpiresExceeded);
}
public void ControllerDiscovery()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
// Act
var provider = GetProvider(
loggerFactory,
typeof(SimpleController).GetTypeInfo(),
typeof(BasicController).GetTypeInfo());
provider.GetDescriptors();
// Assert
// 2 controllers
Assert.Equal(2, sink.Writes.Count);
var controllerModelValues = Assert.IsType<ControllerModelValues>(sink.Writes[0].State);
Assert.NotNull(controllerModelValues);
Assert.Equal("Simple", controllerModelValues.ControllerName);
Assert.Equal(typeof(SimpleController), controllerModelValues.ControllerType);
Assert.Single(controllerModelValues.Actions);
Assert.Empty(controllerModelValues.AttributeRoutes);
Assert.Empty(controllerModelValues.RouteConstraints);
Assert.Empty(controllerModelValues.Attributes);
Assert.Empty(controllerModelValues.Filters);
controllerModelValues = Assert.IsType<ControllerModelValues>(sink.Writes[1].State);
Assert.NotNull(controllerModelValues);
Assert.Equal("Basic", controllerModelValues.ControllerName);
Assert.Equal(typeof(BasicController), controllerModelValues.ControllerType);
Assert.Equal(2, controllerModelValues.Actions.Count);
Assert.Equal("GET", controllerModelValues.Actions[0].HttpMethods.FirstOrDefault());
Assert.Equal("POST", controllerModelValues.Actions[1].HttpMethods.FirstOrDefault());
Assert.Empty(controllerModelValues.AttributeRoutes);
Assert.Empty(controllerModelValues.RouteConstraints);
Assert.NotEmpty(controllerModelValues.Attributes);
Assert.Single(controllerModelValues.Filters);
}
public async Task IsResponseCacheable_SharedMaxAgeOverridesMaxAge_IsAllowed()
{
var utcNow = DateTimeOffset.UtcNow;
var sink = new TestSink();
var context = TestUtils.CreateTestContext(testSink: sink);
context.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
context.HttpContext.Response.Headers.CacheControl = new CacheControlHeaderValue()
{
MaxAge = TimeSpan.FromSeconds(10),
SharedMaxAge = TimeSpan.FromSeconds(15)
}.ToString();
context.HttpContext.Response.Headers.Date = HeaderUtilities.FormatDate(utcNow);
context.ResponseTime = utcNow + TimeSpan.FromSeconds(11);
var policy = new OutputCachePolicyBuilder().Build();
await policy.ServeResponseAsync(context, default);
Assert.True(context.AllowCacheStorage);
Assert.True(context.AllowCacheLookup);
Assert.Empty(sink.Writes);
}
public async Task BindModelAsync_LogsNoFormatterSelectedAndRemoveFromBodyAttribute()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var inputFormatters = new List <IInputFormatter>()
{
new TestInputFormatter(canRead: false),
new TestInputFormatter(canRead: false),
};
var provider = new TestModelMetadataProvider();
provider.ForType <Person>().BindingDetails(d => d.BindingSource = BindingSource.Body);
var bindingContext = GetBindingContext(typeof(Person), metadataProvider: provider);
bindingContext.HttpContext.Request.ContentType = "multipart/form-data";
bindingContext.BinderModelName = bindingContext.ModelName;
var binder = new BodyModelBinder(inputFormatters, new TestHttpRequestStreamReaderFactory(), loggerFactory);
// Act
await binder.BindModelAsync(bindingContext);
// Assert
Assert.Collection(
sink.Writes,
write => Assert.Equal(
$"Attempting to bind model of type '{typeof(Person)}' using the name 'someName' in request data ...", write.State.ToString()),
write => Assert.Equal(
$"Rejected input formatter '{typeof(TestInputFormatter)}' for content type 'multipart/form-data'.", write.State.ToString()),
write => Assert.Equal(
$"Rejected input formatter '{typeof(TestInputFormatter)}' for content type 'multipart/form-data'.", write.State.ToString()),
write => Assert.Equal(
"No input formatter was found to support the content type 'multipart/form-data' for use with the [FromBody] attribute.", write.State.ToString()),
write => Assert.Equal(
$"To use model binding, remove the [FromBody] attribute from the property or parameter named '{bindingContext.ModelName}' with model type '{bindingContext.ModelType}'.", write.State.ToString()),
write => Assert.Equal(
$"Done attempting to bind model of type '{typeof(Person)}' using the name 'someName'.", write.State.ToString()));
}
public async Task WhenRequestIsSecure_AddsHstsHeader()
{
var sink = new TestSink(
TestSink.EnableWithTypeName <HstsMiddleware>,
TestSink.EnableWithTypeName <HstsMiddleware>);
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var builder = new WebHostBuilder()
.ConfigureServices(services =>
{
services.AddSingleton <ILoggerFactory>(loggerFactory);
})
.Configure(app =>
{
app.UseHsts();
app.Run(context =>
{
return(context.Response.WriteAsync("Hello world"));
});
});
var server = new TestServer(builder);
var client = server.CreateClient();
client.BaseAddress = new Uri("https://example.com:5050");
var request = new HttpRequestMessage(HttpMethod.Get, "");
var response = await client.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
Assert.Contains(response.Headers, x => x.Key == HeaderNames.StrictTransportSecurity);
var logMessages = sink.Writes.ToList();
Assert.Single(logMessages);
var message = logMessages.Single();
Assert.Equal(LogLevel.Trace, message.LogLevel);
Assert.Equal("Adding HSTS header to response.", message.State.ToString());
}
public async Task DefaultExcludesCommonLocalhostDomains_DoesNotSetHstsHeader(string host)
{
var sink = new TestSink(
TestSink.EnableWithTypeName <HstsMiddleware>,
TestSink.EnableWithTypeName <HstsMiddleware>);
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var builder = new WebHostBuilder()
.ConfigureServices(services =>
{
services.AddSingleton <ILoggerFactory>(loggerFactory);
})
.Configure(app =>
{
app.UseHsts();
app.Run(context =>
{
return(context.Response.WriteAsync("Hello world"));
});
});
var server = new TestServer(builder);
var client = server.CreateClient();
client.BaseAddress = new Uri($"https://{host}:5050");
var request = new HttpRequestMessage(HttpMethod.Get, "");
var response = await client.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
Assert.Empty(response.Headers);
var logMessages = sink.Writes.ToList();
Assert.Single(logMessages);
var message = logMessages.Single();
Assert.Equal(LogLevel.Debug, message.LogLevel);
Assert.Equal($"The host '{host}' is excluded. Skipping HSTS header.", message.State.ToString(), ignoreCase: true);
}
public async Task BindModelAsync_EnforcesTopLevelRequiredAndLogsSuccessfully_WithEmptyPrefix(
RequiredAttribute attribute,
ParameterDescriptor parameterDescriptor,
ModelMetadata metadata)
{
// Arrange
var expectedKey = string.Empty;
var expectedFieldName = metadata.Name ?? nameof(Person);
var actionContext = GetControllerContext();
var validator = new DataAnnotationsModelValidator(
new ValidationAttributeAdapterProvider(),
attribute,
stringLocalizer: null);
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var parameterBinder = CreateParameterBinder(metadata, validator, loggerFactory: loggerFactory);
var modelBindingResult = ModelBindingResult.Success(null);
// Act
var result = await parameterBinder.BindModelAsync(
actionContext,
CreateMockModelBinder(modelBindingResult),
CreateMockValueProvider(),
parameterDescriptor,
metadata,
"ignoredvalue");
// Assert
Assert.False(actionContext.ModelState.IsValid);
var modelState = Assert.Single(actionContext.ModelState);
Assert.Equal(expectedKey, modelState.Key);
var error = Assert.Single(modelState.Value.Errors);
Assert.Equal(attribute.FormatErrorMessage(expectedFieldName), error.ErrorMessage);
Assert.Equal(4, sink.Writes.Count());
}
public void LogsFeatureIsReadOnly()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink, enabled: true);
var disableRequestSizeLimitResourceFilter = new DisableRequestSizeLimitFilter(loggerFactory);
var authorizationFilterContext = CreateAuthorizationFilterContext(new IFilterMetadata[] { disableRequestSizeLimitResourceFilter });
var httpMaxRequestBodySize = new TestHttpMaxRequestBodySizeFeature();
httpMaxRequestBodySize.IsReadOnly = true;
authorizationFilterContext.HttpContext.Features.Set <IHttpMaxRequestBodySizeFeature>(httpMaxRequestBodySize);
// Act
disableRequestSizeLimitResourceFilter.OnAuthorization(authorizationFilterContext);
// Assert
var write = Assert.Single(sink.Writes);
Assert.Equal($"A request body size limit could not be applied. The IHttpRequestBodySizeFeature for the server is read-only.", write.State.ToString());
}
public void CancellationToken_WithDeadlineAndRequestAborted_DeadlineStatusNotSet()
{
// Arrange
var testSink = new TestSink();
var testLogger = new TestLogger(string.Empty, testSink, true);
var requestLifetimeFeature = new TestHttpRequestLifetimeFeature();
var httpContext = new DefaultHttpContext();
httpContext.Features.Set <IHttpRequestLifetimeFeature>(requestLifetimeFeature);
httpContext.Request.Headers[GrpcProtocolConstants.TimeoutHeader] = "1000S";
var context = CreateServerCallContext(httpContext, testLogger);
context.Initialize();
// Act
requestLifetimeFeature.Abort();
// Assert
Assert.AreNotEqual(StatusCode.DeadlineExceeded, context.Status.StatusCode);
Assert.IsTrue(context.CancellationToken.IsCancellationRequested);
}
public void LogScope_WithoutAnyParameters()
{
// Arrange
var testSink = new TestSink();
var testLogger = new TestLogger("testlogger", testSink, enabled: true);
// Act
var disposable = testLogger.ScopeWithoutAnyParams();
// Assert
Assert.NotNull(disposable);
Assert.Equal(0, testSink.Writes.Count);
Assert.Equal(1, testSink.Scopes.Count);
var scopeContext = testSink.Scopes.First();
var actualLogValues = Assert.IsAssignableFrom<ILogValues>(scopeContext.Scope);
AssertLogValues(new[]
{
new KeyValuePair<string, object>("{OriginalFormat}", TestLoggerExtensions.ScopeWithoutAnyParameters.Message)
},
actualLogValues.GetValues());
Assert.Equal(
TestLoggerExtensions.ScopeWithoutAnyParameters.Message,
actualLogValues.ToString());
}
public async void RouteAsync_Success_LogsCorrectValues()
{
// Arrange
var sink = new TestSink();
var loggerFactory = new TestLoggerFactory(sink);
var context = CreateRouteContext(loggerFactory: loggerFactory);
var handler = new MvcRouteHandler();
// Act
await handler.RouteAsync(context);
// Assert
Assert.Equal(1, sink.Scopes.Count);
var scope = sink.Scopes[0];
Assert.Equal(typeof(MvcRouteHandler).FullName, scope.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", scope.Scope);
// There is a record for IsEnabled and one for WriteCore.
Assert.Equal(2, sink.Writes.Count);
var enabled = sink.Writes[0];
Assert.Equal(typeof(MvcRouteHandler).FullName, enabled.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", enabled.Scope);
Assert.Null(enabled.State);
var write = sink.Writes[1];
Assert.Equal(typeof(MvcRouteHandler).FullName, write.LoggerName);
Assert.Equal("MvcRouteHandler.RouteAsync", write.Scope);
var values = Assert.IsType<MvcRouteHandlerRouteAsyncValues>(write.State);
Assert.Equal("MvcRouteHandler.RouteAsync", values.Name);
Assert.Equal(true, values.ActionSelected);
Assert.Equal(true, values.ActionInvoked);
Assert.Equal(true, values.Handled);
}
