Expand Blazor logging

src/Components/Blazor/Blazor/ref/Microsoft.AspNetCore.Blazor.netstandard2.0.cs

@@ -58,7 +58,7 @@ namespace Microsoft.AspNetCore.Blazor.Rendering
 {
     public partial class WebAssemblyRenderer : Microsoft.AspNetCore.Components.Rendering.Renderer
     {
-        public WebAssemblyRenderer(System.IServiceProvider serviceProvider) : base (default(System.IServiceProvider)) { }
+        public WebAssemblyRenderer(System.IServiceProvider serviceProvider, Microsoft.Extensions.Logging.ILoggerFactory loggerFactory) : base (default(System.IServiceProvider), default(Microsoft.Extensions.Logging.ILoggerFactory)) { }
         public System.Threading.Tasks.Task AddComponentAsync(System.Type componentType, string domElementSelector) { throw null; }
         public System.Threading.Tasks.Task AddComponentAsync<TComponent>(string domElementSelector) where TComponent : Microsoft.AspNetCore.Components.IComponent { throw null; }
         public override System.Threading.Tasks.Task DispatchEventAsync(int eventHandlerId, Microsoft.AspNetCore.Components.Rendering.EventFieldInfo eventFieldInfo, Microsoft.AspNetCore.Components.UIEventArgs eventArgs) { throw null; }

src/Components/Blazor/Blazor/src/Hosting/WebAssemblyBlazorApplicationBuilder.cs

@@ -6,6 +6,8 @@
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Blazor.Rendering;
 using Microsoft.AspNetCore.Components.Builder;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 
 namespace Microsoft.AspNetCore.Blazor.Hosting
 {
@@ -38,7 +40,8 @@ public void AddComponent(Type componentType, string domElementSelector)
 
         public async Task<WebAssemblyRenderer> CreateRendererAsync()
         {
-            var renderer = new WebAssemblyRenderer(Services);
+            var loggerFactory = (ILoggerFactory)Services.GetService(typeof(ILoggerFactory));
+            var renderer = new WebAssemblyRenderer(Services, loggerFactory);
             for (var i = 0; i < Entries.Count; i++)
             {
                 var (componentType, domElementSelector) = Entries[i];

src/Components/Blazor/Blazor/src/Rendering/WebAssemblyRenderer.cs

@@ -8,6 +8,7 @@
 using Microsoft.AspNetCore.Components;
 using Microsoft.AspNetCore.Components.Web;
 using Microsoft.AspNetCore.Components.Rendering;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Blazor.Rendering
 {
@@ -26,8 +27,9 @@ public class WebAssemblyRenderer : Renderer
         /// Constructs an instance of <see cref="WebAssemblyRenderer"/>.
         /// </summary>
         /// <param name="serviceProvider">The <see cref="IServiceProvider"/> to use when initializing components.</param>
-        public WebAssemblyRenderer(IServiceProvider serviceProvider)
-            : base(serviceProvider)
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
+        public WebAssemblyRenderer(IServiceProvider serviceProvider, ILoggerFactory loggerFactory)
+            : base(serviceProvider, loggerFactory)
         {
             // The browser renderer registers and unregisters itself with the static
             // registry. This works well with the WebAssembly runtime, and is simple for the

src/Components/Blazor/Build/test/RazorIntegrationTestBase.cs

@@ -20,6 +20,7 @@
 using Microsoft.CodeAnalysis;
 using Microsoft.CodeAnalysis.CSharp;
 using Microsoft.CodeAnalysis.Razor;
+using Microsoft.Extensions.Logging.Abstractions;
 using Xunit;
 using Xunit.Abstractions;
 using Xunit.Sdk;
@@ -441,7 +442,7 @@ protected class CompileToAssemblyResult
 
         protected class TestRenderer : Renderer
         {
-            public TestRenderer() : base(new TestServiceProvider(), CreateDefaultDispatcher())
+            public TestRenderer() : base(new TestServiceProvider(), NullLoggerFactory.Instance, CreateDefaultDispatcher())
             {
             }
 

src/Components/Components/perf/RenderTreeDiffBuilderBenchmark.cs

@@ -6,6 +6,7 @@
 using BenchmarkDotNet.Attributes;
 using Microsoft.AspNetCore.Components.Rendering;
 using Microsoft.AspNetCore.Components.RenderTree;
+using Microsoft.Extensions.Logging.Abstractions;
 
 namespace Microsoft.AspNetCore.Components.Performance
 {
@@ -87,7 +88,7 @@ public void ComputeDiff_SingleFormField()
         private class FakeRenderer : Renderer
         {
             public FakeRenderer()
-                : base(new TestServiceProvider(), new RendererSynchronizationContext())
+                : base(new TestServiceProvider(), NullLoggerFactory.Instance, new RendererSynchronizationContext())
             {
             }
 

src/Components/Components/ref/Microsoft.AspNetCore.Components.netstandard2.0.cs

@@ -674,7 +674,7 @@ public EventFieldInfo() { }
     }
     public partial class HtmlRenderer : Microsoft.AspNetCore.Components.Rendering.Renderer
     {
-        public HtmlRenderer(System.IServiceProvider serviceProvider, System.Func<string, string> htmlEncoder, Microsoft.AspNetCore.Components.IDispatcher dispatcher) : base (default(System.IServiceProvider)) { }
+        public HtmlRenderer(System.IServiceProvider serviceProvider, Microsoft.Extensions.Logging.ILoggerFactory loggerFactory, Microsoft.AspNetCore.Components.IDispatcher dispatcher, System.Func<string, string> htmlEncoder) : base (default(System.IServiceProvider), default(Microsoft.Extensions.Logging.ILoggerFactory)) { }
         protected override void HandleException(System.Exception exception) { }
         [System.Diagnostics.DebuggerStepThroughAttribute]
         public System.Threading.Tasks.Task<Microsoft.AspNetCore.Components.Rendering.ComponentRenderedText> RenderComponentAsync(System.Type componentType, Microsoft.AspNetCore.Components.ParameterCollection initialParameters) { throw null; }
@@ -692,8 +692,8 @@ public readonly partial struct RenderBatch
     }
     public abstract partial class Renderer : System.IDisposable
     {
-        public Renderer(System.IServiceProvider serviceProvider) { }
-        public Renderer(System.IServiceProvider serviceProvider, Microsoft.AspNetCore.Components.IDispatcher dispatcher) { }
+        public Renderer(System.IServiceProvider serviceProvider, Microsoft.Extensions.Logging.ILoggerFactory loggerFactory) { }
+        public Renderer(System.IServiceProvider serviceProvider, Microsoft.Extensions.Logging.ILoggerFactory loggerFactory, Microsoft.AspNetCore.Components.IDispatcher dispatcher) { }
         public event System.UnhandledExceptionEventHandler UnhandledSynchronizationException { add { } remove { } }
         protected internal virtual void AddToRenderQueue(int componentId, Microsoft.AspNetCore.Components.RenderFragment renderFragment) { }
         protected internal int AssignRootComponentId(Microsoft.AspNetCore.Components.IComponent component) { throw null; }

src/Components/Components/src/Rendering/HtmlRenderer.cs

@@ -7,6 +7,7 @@
 using System.Runtime.ExceptionServices;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Components.RenderTree;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Components.Rendering
 {
@@ -26,10 +27,11 @@ public class HtmlRenderer : Renderer
         /// Initializes a new instance of <see cref="HtmlRenderer"/>.
         /// </summary>
         /// <param name="serviceProvider">The <see cref="IServiceProvider"/> to use to instantiate components.</param>
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
+        /// <param name="dispatcher">The <see cref="IDispatcher"/> to be for invoking user actions into the <see cref="Renderer"/> context.</param>
         /// <param name="htmlEncoder">A <see cref="Func{T, TResult}"/> that will HTML encode the given string.</param>
-        /// <param name="dispatcher"></param>
-        public HtmlRenderer(IServiceProvider serviceProvider, Func<string, string> htmlEncoder, IDispatcher dispatcher)
-            : base(serviceProvider, dispatcher)
+        public HtmlRenderer(IServiceProvider serviceProvider, ILoggerFactory loggerFactory, IDispatcher dispatcher, Func<string, string> htmlEncoder)
+            : base(serviceProvider, loggerFactory, dispatcher)
         {
             _htmlEncoder = htmlEncoder;
         }

src/Components/Components/src/Rendering/Renderer.Log.cs

@@ -0,0 +1,65 @@
+// 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 Microsoft.AspNetCore.Components.Rendering
+{
+    public abstract partial class Renderer
+    {
+        internal static class Log
+        {
+            private static readonly Action<ILogger, int, Type, int, Type, Exception> _initializingChildComponent =
+                LoggerMessage.Define<int, Type, int, Type>(LogLevel.Debug, new EventId(1, "InitializingChildComponent"), "Initializing component {ComponentId} ({ComponentType}) as child of {ParentComponentId} ({ParentComponentId})");
+
+            private static readonly Action<ILogger, int, Type, Exception> _initializingRootComponent =
+                LoggerMessage.Define<int, Type>(LogLevel.Debug, new EventId(2, "InitializingRootComponent"), "Initializing root component {ComponentId} ({ComponentType})");
+
+            private static readonly Action<ILogger, int, Type, Exception> _renderingComponent =
+                LoggerMessage.Define<int, Type>(LogLevel.Debug, new EventId(3, "RenderingComponent"), "Rendering component {ComponentId} of type {ComponentType}");
+
+            private static readonly Action<ILogger, int, Type, Exception> _disposingComponent =
+                LoggerMessage.Define<int, Type>(LogLevel.Debug, new EventId(4, "DisposingComponent"), "Disposing component {ComponentId} of type {ComponentType}");
+
+            private static readonly Action<ILogger, int, string, Exception> _handlingEvent =
+                LoggerMessage.Define<int, string>(LogLevel.Debug, new EventId(5, "HandlingEvent"), "Handling event {EventId} of type '{EventType}'");
+
+            public static void InitializingComponent(ILogger logger, ComponentState componentState, ComponentState parentComponentState)
+            {
+                if (logger.IsEnabled(LogLevel.Debug)) // This is almost always false, so skip the evaluations
+                {
+                    if (parentComponentState == null)
+                    {
+                        _initializingRootComponent(logger, componentState.ComponentId, componentState.Component.GetType(), null);
+                    }
+                    else
+                    {
+                        _initializingChildComponent(logger, componentState.ComponentId, componentState.Component.GetType(), parentComponentState.ComponentId, parentComponentState.Component.GetType(), null);
+                    }
+                }
+            }
+
+            public static void RenderingComponent(ILogger logger, ComponentState componentState)
+            {
+                if (logger.IsEnabled(LogLevel.Debug)) // This is almost always false, so skip the evaluations
+                {
+                    _renderingComponent(logger, componentState.ComponentId, componentState.Component.GetType(), null);
+                }
+            }
+
+            internal static void DisposingComponent(ILogger<Renderer> logger, ComponentState componentState)
+            {
+                if (logger.IsEnabled(LogLevel.Debug)) // This is almost always false, so skip the evaluations
+                {
+                    _disposingComponent(logger, componentState.ComponentId, componentState.Component.GetType(), null);
+                }
+            }
+
+            internal static void HandlingEvent(ILogger<Renderer> logger, int eventHandlerId, UIEventArgs eventArgs)
+            {
+                _handlingEvent(logger, eventHandlerId, eventArgs?.Type ?? "null", null);
+            }
+        }
+    }
+}

src/Components/Components/src/Rendering/Renderer.cs

@@ -7,21 +7,23 @@
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Components.RenderTree;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Components.Rendering
 {
     /// <summary>
     /// Provides mechanisms for rendering hierarchies of <see cref="IComponent"/> instances,
     /// dispatching events to them, and notifying when the user interface is being updated.
     /// </summary>
-    public abstract class Renderer : IDisposable
+    public abstract partial class Renderer : IDisposable
     {
         private readonly ComponentFactory _componentFactory;
         private readonly Dictionary<int, ComponentState> _componentStateById = new Dictionary<int, ComponentState>();
         private readonly RenderBatchBuilder _batchBuilder = new RenderBatchBuilder();
         private readonly Dictionary<int, EventCallback> _eventBindings = new Dictionary<int, EventCallback>();
         private readonly Dictionary<int, int> _eventHandlerIdReplacements = new Dictionary<int, int>();
         private readonly IDispatcher _dispatcher;
+        private readonly ILogger<Renderer> _logger;
 
         private int _nextComponentId = 0; // TODO: change to 'long' when Mono .NET->JS interop supports it
         private bool _isBatchInProgress;
@@ -55,19 +57,33 @@ public event UnhandledExceptionEventHandler UnhandledSynchronizationException
         /// Constructs an instance of <see cref="Renderer"/>.
         /// </summary>
         /// <param name="serviceProvider">The <see cref="IServiceProvider"/> to be used when initializing components.</param>
-        public Renderer(IServiceProvider serviceProvider)
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
+        public Renderer(IServiceProvider serviceProvider, ILoggerFactory loggerFactory)
         {
+            if (serviceProvider is null)
+            {
+                throw new ArgumentNullException(nameof(serviceProvider));
+            }
+
+            if (loggerFactory is null)
+            {
+                throw new ArgumentNullException(nameof(loggerFactory));
+            }
+
             _componentFactory = new ComponentFactory(serviceProvider);
+            _logger = loggerFactory.CreateLogger<Renderer>();
         }
 
         /// <summary>
         /// Constructs an instance of <see cref="Renderer"/>.
         /// </summary>
         /// <param name="serviceProvider">The <see cref="IServiceProvider"/> to be used when initializing components.</param>
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
         /// <param name="dispatcher">The <see cref="IDispatcher"/> to be for invoking user actions into the <see cref="Renderer"/> context.</param>
-        public Renderer(IServiceProvider serviceProvider, IDispatcher dispatcher) : this(serviceProvider)
+        public Renderer(IServiceProvider serviceProvider, ILoggerFactory loggerFactory, IDispatcher dispatcher)
+            : this(serviceProvider, loggerFactory)
         {
-            _dispatcher = dispatcher;
+            _dispatcher = dispatcher ?? throw new ArgumentNullException(nameof(dispatcher));
         }
 
         /// <summary>
@@ -189,6 +205,7 @@ private ComponentState AttachAndInitComponent(IComponent component, int parentCo
             var componentId = _nextComponentId++;
             var parentComponentState = GetOptionalComponentState(parentComponentId);
             var componentState = new ComponentState(this, componentId, component, parentComponentState);
+            Log.InitializingComponent(_logger, componentState, parentComponentState);
             _componentStateById.Add(componentId, componentState);
             component.Configure(new RenderHandle(this, componentId));
             return componentState;
@@ -220,6 +237,8 @@ public virtual Task DispatchEventAsync(int eventHandlerId, EventFieldInfo fieldI
                 throw new ArgumentException($"There is no event handler with ID {eventHandlerId}");
             }
 
+            Log.HandlingEvent(_logger, eventHandlerId, eventArgs);
+
             if (fieldInfo != null)
             {
                 var latestEquivalentEventHandlerId = FindLatestEventHandlerIdInChain(eventHandlerId);
@@ -613,14 +632,17 @@ private void NotifyRenderCompleted(ComponentState state, ref List<Task> batch)
 
         private void RenderInExistingBatch(RenderQueueEntry renderQueueEntry)
         {
-            renderQueueEntry.ComponentState
-                .RenderIntoBatch(_batchBuilder, renderQueueEntry.RenderFragment);
+            var componentState = renderQueueEntry.ComponentState;
+            Log.RenderingComponent(_logger, componentState);
+            componentState.RenderIntoBatch(_batchBuilder, renderQueueEntry.RenderFragment);
 
             // Process disposal queue now in case it causes further component renders to be enqueued
             while (_batchBuilder.ComponentDisposalQueue.Count > 0)
             {
                 var disposeComponentId = _batchBuilder.ComponentDisposalQueue.Dequeue();
-                GetRequiredComponentState(disposeComponentId).DisposeInBatch(_batchBuilder);
+                var disposeComponentState = GetRequiredComponentState(disposeComponentId);
+                Log.DisposingComponent(_logger, disposeComponentState);
+                disposeComponentState.DisposeInBatch(_batchBuilder);
                 _componentStateById.Remove(disposeComponentId);
                 _batchBuilder.DisposedComponentIds.Append(disposeComponentId);
             }
@@ -710,6 +732,8 @@ protected virtual void Dispose(bool disposing)
         {
             foreach (var componentState in _componentStateById.Values)
             {
+                Log.DisposingComponent(_logger, componentState);
+
                 if (componentState.Component is IDisposable disposable)
                 {
                     try