Skip to content

Log unhandled exceptions to custom logger #19606

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 13 commits into from
Mar 13, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 10 additions & 3 deletions src/Components/Web.JS/dist/Release/blazor.server.js

Large diffs are not rendered by default.

2 changes: 1 addition & 1 deletion src/Components/Web.JS/dist/Release/blazor.webassembly.js

Large diffs are not rendered by default.

4 changes: 2 additions & 2 deletions src/Components/Web.JS/src/Platform/Mono/MonoPlatform.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Copy link
Member Author

@SteveSandersonMS SteveSandersonMS Mar 5, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I removed the WASM: prefix because it serves no purpose. Developers who call Console.WriteLine should be able to choose exactly what string gets logged, without the framework enforcing an arbitrary prefix.

showErrorNotification();
};
module.preRun = [];
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -31,6 +32,7 @@ public WebAssemblyRenderer(IServiceProvider serviceProvider, ILoggerFactory logg
{
// 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;
Expand Down Expand Up @@ -101,17 +103,16 @@ protected override Task UpdateDisplayAsync(in RenderBatch batch)
/// <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);
}
}

Expand Down Expand Up @@ -192,5 +193,31 @@ public IncomingEventInfo(ulong eventHandlerId, EventFieldInfo eventFieldInfo, Ev
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);
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -2,26 +2,170 @@
// 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;
}

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));
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is a bit weird that the logger does this. Does the ConsoleLogger do the same thing?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would look at what we do in ASP.NET Core and strive for consistency with what is there.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point. Changing as per #19606 (comment)


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
Expand Down
Original file line number Diff line number Diff line change
@@ -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()
{
Expand Down
6 changes: 3 additions & 3 deletions src/Components/test/E2ETest/Tests/ErrorNotificationTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@ protected override void InitializeAsyncCore()
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]
Expand All @@ -38,7 +38,7 @@ public void ShowsErrorNotification_OnError_Dismiss()
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));
Expand All @@ -52,7 +52,7 @@ public void ShowsErrorNotification_OnError_Dismiss()
[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"));

Expand Down
Loading