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

Log unhandled exceptions to custom logger (#19606)

This commit is contained in:
Steve Sanderson 2020-03-13 10:40:02 +00:00 committed by GitHub
parent 343816f4d1
commit 9343d2bca0
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
13 changed files with 451 additions and 22 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

13
src/Components/Web.JS/dist/Release/blazor.server.js generated vendored
View File

File diff suppressed because one or more lines are too long

2
src/Components/Web.JS/dist/Release/blazor.webassembly.js generated vendored
View File

File diff suppressed because one or more lines are too long

4
src/Components/Web.JS/src/Platform/Mono/MonoPlatform.ts
View File

@ -160,10 +160,10 @@ function createEmscriptenModuleInstance(resourceLoader: WebAssemblyResourceLoade
const module = {} as typeof Module;
const suppressMessages = ['DEBUGGING ENABLED'];
module.print = line => (suppressMessages.indexOf(line) < 0 && console.log(`WASM: ${line}`));
module.print = line => (suppressMessages.indexOf(line) < 0 && console.log(line));
module.printErr = line => {
console.error(`WASM: ${line}`);
console.error(line);
showErrorNotification();
};
module.preRun = [];

33
src/Components/WebAssembly/WebAssembly/src/Rendering/WebAssemblyRenderer.cs
View File

@ -16,6 +16,7 @@ namespace Microsoft.AspNetCore.Components.WebAssembly.Rendering
/// </summary>
internal class WebAssemblyRenderer : Renderer
{
private readonly ILogger _logger;
private readonly int _webAssemblyRendererId;
private bool isDispatchingEvent;
@ -31,6 +32,7 @@ namespace Microsoft.AspNetCore.Components.WebAssembly.Rendering
{
// The WebAssembly renderer registers and unregisters itself with the static registry
_webAssemblyRendererId = RendererRegistry.Add(this);
_logger = loggerFactory.CreateLogger<WebAssemblyRenderer>();
}
public override Dispatcher Dispatcher => NullDispatcher.Instance;
@ -101,17 +103,16 @@ namespace Microsoft.AspNetCore.Components.WebAssembly.Rendering
/// <inheritdoc />
protected override void HandleException(Exception exception)
{
Console.Error.WriteLine($"Unhandled exception rendering component:");
if (exception is AggregateException aggregateException)
{
foreach (var innerException in aggregateException.Flatten().InnerExceptions)
{
Console.Error.WriteLine(innerException);
Log.UnhandledExceptionRenderingComponent(_logger, innerException);
}
}
else
{
Console.Error.WriteLine(exception);
Log.UnhandledExceptionRenderingComponent(_logger, exception);
}
}
@ -192,5 +193,31 @@ namespace Microsoft.AspNetCore.Components.WebAssembly.Rendering
TaskCompletionSource = new TaskCompletionSource<object>();
}
}
private static class Log
{
private static readonly Action<ILogger, string, Exception> _unhandledExceptionRenderingComponent;
private static class EventIds
{
public static readonly EventId UnhandledExceptionRenderingComponent = new EventId(100, "ExceptionRenderingComponent");
}
static Log()
{
_unhandledExceptionRenderingComponent = LoggerMessage.Define<string>(
LogLevel.Critical,
EventIds.UnhandledExceptionRenderingComponent,
"Unhandled exception rendering component: {Message}");
}
public static void UnhandledExceptionRenderingComponent(ILogger logger, Exception exception)
{
_unhandledExceptionRenderingComponent(
logger,
exception.Message,
exception);
}
}
}
}

150
src/Components/WebAssembly/WebAssembly/src/Services/WebAssemblyConsoleLogger.cs
View File

@ -2,12 +2,40 @@
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System;
using System.Text;
using Microsoft.Extensions.Logging;
using Microsoft.JSInterop;
namespace Microsoft.AspNetCore.Components.WebAssembly.Services
{
internal class WebAssemblyConsoleLogger<T> : ILogger<T>, ILogger
{
private static readonly string _loglevelPadding = ": ";
private static readonly string _messagePadding;
private static readonly string _newLineWithMessagePadding;
private static readonly StringBuilder _logBuilder = new StringBuilder();
private readonly string _name;
private readonly IJSInProcessRuntime _jsRuntime;
static WebAssemblyConsoleLogger()
{
var logLevelString = GetLogLevelString(LogLevel.Information);
_messagePadding = new string(' ', logLevelString.Length + _loglevelPadding.Length);
_newLineWithMessagePadding = Environment.NewLine + _messagePadding;
}
public WebAssemblyConsoleLogger(IJSRuntime jsRuntime)
: this(string.Empty, (IJSInProcessRuntime)jsRuntime) // Cast for DI
{
}
public WebAssemblyConsoleLogger(string name, IJSInProcessRuntime jsRuntime)
{
_name = name ?? throw new ArgumentNullException(nameof(name));
_jsRuntime = jsRuntime ?? throw new ArgumentNullException(nameof(jsRuntime));
}
public IDisposable BeginScope<TState>(TState state)
{
return NoOpDisposable.Instance;
@ -15,13 +43,129 @@ namespace Microsoft.AspNetCore.Components.WebAssembly.Services
public bool IsEnabled(LogLevel logLevel)
{
return logLevel >= LogLevel.Warning;
return logLevel >= LogLevel.Warning && logLevel != LogLevel.None;
}
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
var formattedMessage = formatter(state, exception);
Console.WriteLine($"[{logLevel}] {formattedMessage}");
if (!IsEnabled(logLevel))
{
return;
}
if (formatter == null)
{
throw new ArgumentNullException(nameof(formatter));
}
var message = formatter(state, exception);
if (!string.IsNullOrEmpty(message) || exception != null)
{
WriteMessage(logLevel, _name, eventId.Id, message, exception);
}
}
private void WriteMessage(LogLevel logLevel, string logName, int eventId, string message, Exception exception)
{
lock (_logBuilder)
{
try
{
CreateDefaultLogMessage(_logBuilder, logLevel, logName, eventId, message, exception);
var formattedMessage = _logBuilder.ToString();
switch (logLevel)
{
case LogLevel.Trace:
case LogLevel.Debug:
// Although https://console.spec.whatwg.org/#loglevel-severity claims that
// "console.debug" and "console.log" are synonyms, that doesn't match the
// behavior of browsers in the real world. Chromium only displays "debug"
// messages if you enable "Verbose" in the filter dropdown (which is off
// by default). As such "console.debug" is the best choice for messages
// with a lower severity level than "Information".
_jsRuntime.InvokeVoid("console.debug", formattedMessage);
break;
case LogLevel.Information:
_jsRuntime.InvokeVoid("console.info", formattedMessage);
break;
case LogLevel.Warning:
_jsRuntime.InvokeVoid("console.warn", formattedMessage);
break;
case LogLevel.Error:
_jsRuntime.InvokeVoid("console.error", formattedMessage);
break;
case LogLevel.Critical:
// Writing to Console.Error is even more severe than calling console.error,
// because it also causes the error UI (gold bar) to appear. We use Console.Error
// as the signal for triggering that because it's what the underlying dotnet.wasm
// runtime will do if it encounters a truly severe error outside the Blazor
// code paths.
Console.Error.WriteLine(formattedMessage);
break;
default: // LogLevel.None or invalid enum values
Console.WriteLine(formattedMessage);
break;
}
}
finally
{
_logBuilder.Clear();
}
}
}
private void CreateDefaultLogMessage(StringBuilder logBuilder, LogLevel logLevel, string logName, int eventId, string message, Exception exception)
{
logBuilder.Append(GetLogLevelString(logLevel));
logBuilder.Append(_loglevelPadding);
logBuilder.Append(logName);
logBuilder.Append("[");
logBuilder.Append(eventId);
logBuilder.Append("]");
if (!string.IsNullOrEmpty(message))
{
// message
logBuilder.AppendLine();
logBuilder.Append(_messagePadding);
var len = logBuilder.Length;
logBuilder.Append(message);
logBuilder.Replace(Environment.NewLine, _newLineWithMessagePadding, len, message.Length);
}
// Example:
// System.InvalidOperationException
// at Namespace.Class.Function() in File:line X
if (exception != null)
{
// exception message
logBuilder.AppendLine();
logBuilder.Append(exception.ToString());
}
}
private static string GetLogLevelString(LogLevel logLevel)
{
switch (logLevel)
{
case LogLevel.Trace:
return "trce";
case LogLevel.Debug:
return "dbug";
case LogLevel.Information:
return "info";
case LogLevel.Warning:
return "warn";
case LogLevel.Error:
return "fail";
case LogLevel.Critical:
return "crit";
default:
throw new ArgumentOutOfRangeException(nameof(logLevel));
}
}
private class NoOpDisposable : IDisposable

15
src/Components/WebAssembly/WebAssembly/src/Services/WebAssemblyLoggerFactory.cs
View File

@ -1,19 +1,28 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Microsoft.JSInterop;
namespace Microsoft.AspNetCore.Components.WebAssembly.Services
{
internal class WebAssemblyLoggerFactory : ILoggerFactory
{
public void AddProvider(ILoggerProvider provider)
private readonly IJSInProcessRuntime _jsRuntime;
public WebAssemblyLoggerFactory(IServiceProvider services)
{
// No-op
_jsRuntime = (IJSInProcessRuntime)services.GetRequiredService<IJSRuntime>();
}
// We might implement this in the future, but it's not required currently
public void AddProvider(ILoggerProvider provider)
=> throw new NotSupportedException();
public ILogger CreateLogger(string categoryName)
=> new WebAssemblyConsoleLogger<object>();
=> new WebAssemblyConsoleLogger<object>(categoryName, _jsRuntime);
public void Dispose()
{

6
src/Components/test/E2ETest/Tests/ErrorNotificationTest.cs
View File

@ -29,7 +29,7 @@ namespace Microsoft.AspNetCore.Components.E2ETest.Tests
Navigate(ServerPathBase, noReload: _serverFixture.ExecutionMode == ExecutionMode.Client);
Browser.MountTestComponent<ErrorComponent>();
Browser.Exists(By.Id("blazor-error-ui"));
Browser.Exists(By.TagName("button"));
Browser.Exists(By.Id("throw-simple-exception"));
}
[Fact]
@ -38,7 +38,7 @@ namespace Microsoft.AspNetCore.Components.E2ETest.Tests
var errorUi = Browser.FindElement(By.Id("blazor-error-ui"));
Assert.Equal("none", errorUi.GetCssValue("display"));
var causeErrorButton = Browser.FindElement(By.TagName("button"));
var causeErrorButton = Browser.FindElement(By.Id("throw-simple-exception"));
causeErrorButton.Click();
Browser.Exists(By.CssSelector("#blazor-error-ui[style='display: block;']"), TimeSpan.FromSeconds(10));
@ -52,7 +52,7 @@ namespace Microsoft.AspNetCore.Components.E2ETest.Tests
[Fact]
public void ShowsErrorNotification_OnError_Reload()
{
var causeErrorButton = Browser.Exists(By.TagName("button"));
var causeErrorButton = Browser.Exists(By.Id("throw-simple-exception"));
var errorUi = Browser.FindElement(By.Id("blazor-error-ui"));
Assert.Equal("none", errorUi.GetCssValue("display"));

130
src/Components/test/E2ETest/Tests/WebAssemblyLoggingTest.cs Normal file
View File

@ -0,0 +1,130 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System;
using BasicTestApp;
using Microsoft.AspNetCore.Components.E2ETest.Infrastructure;
using Microsoft.AspNetCore.Components.E2ETest.Infrastructure.ServerFixtures;
using Microsoft.AspNetCore.E2ETesting;
using OpenQA.Selenium;
using Xunit;
using Xunit.Abstractions;
namespace Microsoft.AspNetCore.Components.E2ETest.Tests
{
public class WebAssemblyLoggingTest : ServerTestBase<ToggleExecutionModeServerFixture<Program>>
{
public WebAssemblyLoggingTest(
BrowserFixture browserFixture,
ToggleExecutionModeServerFixture<Program> serverFixture,
ITestOutputHelper output)
: base(browserFixture, serverFixture, output)
{
}
protected override void InitializeAsyncCore()
{
Navigate(ServerPathBase, noReload: false);
Browser.MountTestComponent<ErrorComponent>();
Browser.Exists(By.Id("blazor-error-ui"));
var errorUi = Browser.FindElement(By.Id("blazor-error-ui"));
Assert.Equal("none", errorUi.GetCssValue("display"));
}
[Fact]
public void LogsSimpleExceptionsUsingLogger()
{
Browser.FindElement(By.Id("throw-simple-exception")).Click();
Browser.Exists(By.CssSelector("#blazor-error-ui[style='display: block;']"), TimeSpan.FromSeconds(10));
AssertLogContainsCriticalMessages(
"crit: Microsoft.AspNetCore.Components.WebAssembly.Rendering.WebAssemblyRenderer[100]",
"[Custom logger] Unhandled exception rendering component: Doing something that won't work!",
"System.InvalidTimeZoneException: Doing something that won't work!",
"at BasicTestApp.ErrorComponent.ThrowSimple");
}
[Fact]
public void LogsInnerExceptionsUsingLogger()
{
Browser.FindElement(By.Id("throw-inner-exception")).Click();
Browser.Exists(By.CssSelector("#blazor-error-ui[style='display: block;']"), TimeSpan.FromSeconds(10));
AssertLogContainsCriticalMessages(
"crit: Microsoft.AspNetCore.Components.WebAssembly.Rendering.WebAssemblyRenderer[100]",
"[Custom logger] Unhandled exception rendering component: Here is the outer exception",
"System.InvalidTimeZoneException: Here is the outer exception ---> System.ArithmeticException: Here is the inner exception",
"at BasicTestApp.ErrorComponent.ThrowInner");
}
[Fact]
public void LogsAggregateExceptionsUsingLogger()
{
Browser.FindElement(By.Id("throw-aggregate-exception")).Click();
Browser.Exists(By.CssSelector("#blazor-error-ui[style='display: block;']"), TimeSpan.FromSeconds(10));
AssertLogContainsCriticalMessages(
"crit: Microsoft.AspNetCore.Components.WebAssembly.Rendering.WebAssemblyRenderer[100]",
"[Custom logger] Unhandled exception rendering component: Aggregate exception 1",
"System.InvalidTimeZoneException: Aggregate exception 1",
"[Custom logger] Unhandled exception rendering component: Aggregate exception 2",
"System.InvalidTimeZoneException: Aggregate exception 2",
"[Custom logger] Unhandled exception rendering component: Aggregate exception 3",
"System.InvalidTimeZoneException: Aggregate exception 3");
}
[Fact]
public void LogsUsingCustomLogger()
{
Browser.MountTestComponent<LoggingComponent>();
Browser.Exists(By.Id("blazor-error-ui"));
Browser.Exists(By.Id("log-trace"));
((IJavaScriptExecutor)Browser).ExecuteScript("console.info('Test log message')");
// None of these severity levels are displayed by default, so at the end
// we'll continue to see "Test log message" as the most recent output
Browser.FindElement(By.Id("log-none")).Click();
Browser.FindElement(By.Id("log-trace")).Click();
Browser.FindElement(By.Id("log-debug")).Click();
Browser.FindElement(By.Id("log-information")).Click();
AssertLastLogMessage(LogLevel.Info, "Test log message");
// These severity levels are displayed
Browser.FindElement(By.Id("log-warning")).Click();
AssertLastLogMessage(LogLevel.Warning, "[Custom logger] This is a Warning message with count=5");
Browser.FindElement(By.Id("log-error")).Click();
AssertLastLogMessage(LogLevel.Severe, "[Custom logger] This is a Error message with count=6");
// All the preceding levels don't cause the error UI to appear
var errorUi = Browser.FindElement(By.Id("blazor-error-ui"));
Assert.Equal("none", errorUi.GetCssValue("display"));
// ... but "Critical" level does
Browser.FindElement(By.Id("log-critical")).Click();
AssertLastLogMessage(LogLevel.Severe, "[Custom logger] This is a Critical message with count=7");
Assert.Equal("block", errorUi.GetCssValue("display"));
}
void AssertLastLogMessage(LogLevel level, string message)
{
var log = Browser.Manage().Logs.GetLog(LogType.Browser);
var lastEntry = log[log.Count - 1];
Assert.Equal(level, lastEntry.Level);
// Selenium prefixes the message with various bits of internal info, so use "Contains"
Assert.Contains(message, lastEntry.Message);
}
void AssertLogContainsCriticalMessages(params string[] messages)
{
var log = Browser.Manage().Logs.GetLog(LogType.Browser);
foreach (var message in messages)
{
Assert.Contains(log, entry =>
{
return entry.Level == LogLevel.Severe
&& entry.Message.Contains(message);
});
}
}
}
}

26
src/Components/test/testassets/BasicTestApp/ErrorComponent.razor
View File

@ -1,16 +1,34 @@
<div>
<h2>Error throwing button</h2>
<h2>Error throwing buttons</h2>
<p>
<button @onclick="@(IncrementCount)">Click me</button>
<button id="throw-simple-exception" @onclick="@(ThrowSimple)">Throw simple exception</button>
<button id="throw-inner-exception" @onclick="@(ThrowInner)">Throw with inner exception</button>
<button id="throw-aggregate-exception" @onclick="@(ThrowAggregate)">Throw aggregate exception</button>
</p>
</div>
@code {
int currentCount = 0;
void IncrementCount()
void ThrowSimple()
{
currentCount++;
throw new NotImplementedException("Doing something that won't work!");
throw new InvalidTimeZoneException("Doing something that won't work!");
}
void ThrowInner()
{
currentCount++;
throw new InvalidTimeZoneException("Here is the outer exception",
new ArithmeticException("Here is the inner exception"));
}
void ThrowAggregate()
{
currentCount++;
throw new AggregateException(
new InvalidTimeZoneException("Aggregate exception 1"),
new InvalidTimeZoneException("Aggregate exception 2"),
new InvalidTimeZoneException("Aggregate exception 3"));
}
}

1
src/Components/test/testassets/BasicTestApp/Index.razor
View File

@ -52,6 +52,7 @@
<option value="BasicTestApp.LimitCounterComponent">Limit counter component</option>
<option value="BasicTestApp.LocalizedText">Localized Text</option>
<option value="BasicTestApp.LogicalElementInsertionCases">Logical element insertion cases</option>
<option value="BasicTestApp.LoggingComponent">Logging</option>
<option value="BasicTestApp.LongRunningInterop">Long running interop</option>
<option value="BasicTestApp.MarkupBlockComponent">Markup blocks</option>
<option value="BasicTestApp.MouseEventComponent">Mouse events</option>

25
src/Components/test/testassets/BasicTestApp/LoggingComponent.razor Normal file
View File

@ -0,0 +1,25 @@
@using Microsoft.Extensions.Logging
@inject ILoggerFactory LoggerFactory
<h2>Logging buttons</h2>
<p>
<button id="log-none" @onclick="@(() => Log(LogLevel.None))">Log None</button>
<button id="log-trace" @onclick="@(() => Log(LogLevel.Trace))">Log Trace</button>
<button id="log-debug" @onclick="@(() => Log(LogLevel.Debug))">Log Debug</button>
<button id="log-information" @onclick="@(() => Log(LogLevel.Information))">Log Information</button>
<button id="log-warning" @onclick="@(() => Log(LogLevel.Warning))">Log Warning</button>
<button id="log-error" @onclick="@(() => Log(LogLevel.Error))">Log Error</button>
<button id="log-critical" @onclick="@(() => Log(LogLevel.Critical))">Log Critical</button>
</p>
@code {
int currentCount = 0;
void Log(LogLevel level)
{
currentCount++;
var logger = LoggerFactory.CreateLogger<ErrorComponent>();
logger.Log(level, $"This is a {level} message with count={{count}}", currentCount);
}
}

56
src/Components/test/testassets/BasicTestApp/PrependMessageLoggerFactory.cs Normal file
View File

@ -0,0 +1,56 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System;
using Microsoft.Extensions.Logging;
namespace BasicTestApp
{
// The goal for this class is to make it possible for E2E tests to observe that a custom
// logger factory can be plugged in and gets used when logging unhandled exceptions.
// However, it's valuable to pass through all calls to the default implementation too
// so that if any defect in the underlying implementation would break tests, we still see it.
public class PrependMessageLoggerFactory : ILoggerFactory
{
private readonly string _message;
private readonly ILoggerFactory _underlyingFactory;
public PrependMessageLoggerFactory(string message, ILoggerFactory underlyingFactory)
{
_message = message;
_underlyingFactory = underlyingFactory;
}
public void AddProvider(ILoggerProvider provider)
=> _underlyingFactory.AddProvider(provider);
public ILogger CreateLogger(string categoryName)
=> new PrependMessageLogger(_message, _underlyingFactory.CreateLogger(categoryName));
public void Dispose()
=> _underlyingFactory.Dispose();
private class PrependMessageLogger : ILogger
{
private readonly string _message;
private readonly ILogger _underlyingLogger;
public PrependMessageLogger(string message, ILogger underlyingLogger)
{
_message = message;
_underlyingLogger = underlyingLogger;
}
public IDisposable BeginScope<TState>(TState state)
=> _underlyingLogger.BeginScope(state);
public bool IsEnabled(LogLevel logLevel)
=> _underlyingLogger.IsEnabled(logLevel);
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
=> _underlyingLogger.Log(logLevel, eventId, state, exception,
(state, exception) => $"[{_message}] {formatter(state, exception)}");
}
}
}

12
src/Components/test/testassets/BasicTestApp/Program.cs
View File

@ -3,6 +3,7 @@
using System;
using System.Globalization;
using System.Linq;
using System.Runtime.InteropServices;
using System.Threading.Tasks;
using BasicTestApp.AuthTest;
@ -11,6 +12,7 @@ using Microsoft.AspNetCore.Components.WebAssembly.Hosting;
using Microsoft.AspNetCore.Components.WebAssembly.Http;
using Microsoft.AspNetCore.Components.WebAssembly.Services;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
namespace BasicTestApp
{
@ -42,6 +44,16 @@ namespace BasicTestApp
policy.RequireAssertion(ctx => ctx.User.Identity.Name?.StartsWith("B") ?? false));
});
// Replace the default logger with a custom one that wraps it
var originalLoggerDescriptor = builder.Services.Single(d => d.ServiceType == typeof(ILoggerFactory));
builder.Services.AddSingleton<ILoggerFactory>(services =>
{
var originalLogger = (ILoggerFactory)Activator.CreateInstance(
originalLoggerDescriptor.ImplementationType,
new object[] { services });
return new PrependMessageLoggerFactory("Custom logger", originalLogger);
});
await builder.Build().RunAsync();
}