Add logging and scope for ViewComponent

samples/MvcSample.Web/Startup.cs

@@ -7,6 +7,7 @@ using Microsoft.AspNet.Localization;
 using Microsoft.AspNet.Mvc;
 using Microsoft.AspNet.Mvc.Razor;
 using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
 using MvcSample.Web.Filters;
 using MvcSample.Web.Services;
 
@@ -34,8 +35,18 @@ namespace MvcSample.Web
             return services.BuildServiceProvider();
         }
 
-        public void Configure(IApplicationBuilder app)
+        public void Configure(IApplicationBuilder app, ILoggerFactory loggerFactory)
         {
+            loggerFactory.AddConsole((category, level) =>
+            {
+                if (category.StartsWith("Microsoft."))
+                {
+                    return level >= LogLevel.Information;
+                }
+
+                return level >= LogLevel.Verbose;
+            });
+
             app.UseStatusCodePages();
             app.UseFileServer();
 

samples/MvcSample.Web/project.json

@@ -1,36 +1,37 @@
 {
-    "commands": {
+  "commands": {
-        "web": "Microsoft.AspNet.Hosting server=Microsoft.AspNet.Server.WebListener server.urls=http://localhost:5001",
+    "web": "Microsoft.AspNet.Hosting server=Microsoft.AspNet.Server.WebListener server.urls=http://localhost:5001",
-        "kestrel": "Microsoft.AspNet.Hosting --server Microsoft.AspNet.Server.Kestrel --server.urls http://localhost:5000"
+    "kestrel": "Microsoft.AspNet.Hosting --server Microsoft.AspNet.Server.Kestrel --server.urls http://localhost:5000"
-    },
+  },
-    "compilationOptions": {
+  "compilationOptions": {
-        "warningsAsErrors": true
+    "warningsAsErrors": true
-    },
+  },
-    "dependencies": {
+  "dependencies": {
-        "Microsoft.AspNet.Server.Kestrel": "1.0.0-*",
+    "Microsoft.AspNet.Server.Kestrel": "1.0.0-*",
-        "Microsoft.AspNet.Diagnostics": "1.0.0-*",
+    "Microsoft.AspNet.Diagnostics": "1.0.0-*",
-        "Microsoft.AspNet.Localization": "1.0.0-*",
+    "Microsoft.AspNet.Localization": "1.0.0-*",
-        "Microsoft.AspNet.Mvc": "6.0.0-*",
+    "Microsoft.AspNet.Mvc": "6.0.0-*",
-        "Microsoft.AspNet.Mvc.Formatters.Xml": "6.0.0-*",
+    "Microsoft.AspNet.Mvc.Formatters.Xml": "6.0.0-*",
-        "Microsoft.AspNet.Mvc.WebApiCompatShim": "6.0.0-*",
+    "Microsoft.AspNet.Mvc.WebApiCompatShim": "6.0.0-*",
-        "Microsoft.AspNet.Server.IIS": "1.0.0-*",
+    "Microsoft.AspNet.Server.IIS": "1.0.0-*",
-        "Microsoft.AspNet.Server.WebListener": "1.0.0-*",
+    "Microsoft.AspNet.Server.WebListener": "1.0.0-*",
-        "Microsoft.AspNet.Session": "1.0.0-*",
+    "Microsoft.AspNet.Session": "1.0.0-*",
-        "Microsoft.AspNet.StaticFiles": "1.0.0-*",
+    "Microsoft.AspNet.StaticFiles": "1.0.0-*",
-        "Microsoft.Extensions.Configuration.Json": "1.0.0-*"
+    "Microsoft.Extensions.Configuration.Json": "1.0.0-*",
-    },
+    "Microsoft.Extensions.Logging.Console": "1.0.0-*"
-    "frameworks": {
+  },
-        "dnx451": { },
+  "frameworks": {
-        "dnxcore50": { }
+    "dnx451": { },
-    },
+    "dnxcore50": { }
-    "exclude": [
+  },
-        "wwwroot",
+  "exclude": [
-        "node_modules",
+    "wwwroot",
-        "bower_components"
+    "node_modules",
-    ],
+    "bower_components"
-    "publishExclude": [
+  ],
-        "**.user",
+  "publishExclude": [
-        "**.vspscc"
+    "**.user",
-    ],
+    "**.vspscc"
-    "webroot": "wwwroot"
+  ],
+  "webroot": "wwwroot"
 }

src/Microsoft.AspNet.Mvc.ViewFeatures/Logging/DefaultViewComponentInvokerLoggerExtensions.cs

@@ -0,0 +1,79 @@
+// 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 System.Collections.Generic;
+using Microsoft.AspNet.Mvc.ViewComponents;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.AspNet.Mvc.ViewFeatures.Logging
+{
+    public static class DefaultViewComponentInvokerLoggerExtensions
+    {
+        private static readonly Action<ILogger, string, Exception> _viewComponentExecuting;
+        private static readonly Action<ILogger, string, double, string, Exception> _viewComponentExecuted;
+
+        static DefaultViewComponentInvokerLoggerExtensions()
+        {
+            _viewComponentExecuting = LoggerMessage.Define<string>(
+                LogLevel.Verbose,
+                1,
+                "Executing view component {ViewComponentName}");
+
+            _viewComponentExecuted = LoggerMessage.Define<string, double, string>(
+                LogLevel.Verbose,
+                2,
+                "Executed view component {ViewComponentName} in {ElapsedMilliseconds}ms and returned " +
+                "{ViewComponentResult}");
+        }
+
+        public static IDisposable ViewComponentScope(this ILogger logger, ViewComponentContext context)
+        {
+            return logger.BeginScopeImpl(new ViewComponentLogScope(context.ViewComponentDescriptor));
+        }
+
+        public static void ViewComponentExecuting(this ILogger logger, ViewComponentContext context)
+        {
+            _viewComponentExecuting(logger, context.ViewComponentDescriptor.DisplayName, null);
+        }
+
+        public static void ViewComponentExecuted(
+            this ILogger logger,
+            ViewComponentContext context,
+            int startTime,
+            object result)
+        {
+            var elapsed = new TimeSpan(Environment.TickCount - startTime);
+            _viewComponentExecuted(
+                logger,
+                context.ViewComponentDescriptor.DisplayName,
+                elapsed.TotalMilliseconds,
+                Convert.ToString(result),
+                null);
+        }
+
+        private class ViewComponentLogScope : ILogValues
+        {
+            private readonly ViewComponentDescriptor _descriptor;
+
+            public ViewComponentLogScope(ViewComponentDescriptor descriptor)
+            {
+                _descriptor = descriptor;
+            }
+
+            public IEnumerable<KeyValuePair<string, object>> GetValues()
+            {
+                return new KeyValuePair<string, object>[]
+                {
+                    new KeyValuePair<string, object>("ViewComponentName", _descriptor.DisplayName),
+                    new KeyValuePair<string, object>("ViewComponentId", _descriptor.Id),
+                };
+            }
+
+            public override string ToString()
+            {
+                return _descriptor.DisplayName;
+            }
+        }
+    }
+}

src/Microsoft.AspNet.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvoker.cs

@@ -11,6 +11,8 @@ using Microsoft.AspNet.Mvc.Diagnostics;
 using Microsoft.AspNet.Mvc.Infrastructure;
 using Microsoft.AspNet.Mvc.Rendering;
 using Microsoft.AspNet.Mvc.ViewFeatures;
+using Microsoft.AspNet.Mvc.ViewFeatures.Logging;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNet.Mvc.ViewComponents
 {
@@ -19,11 +21,13 @@ namespace Microsoft.AspNet.Mvc.ViewComponents
         private readonly ITypeActivatorCache _typeActivatorCache;
         private readonly IViewComponentActivator _viewComponentActivator;
         private readonly DiagnosticSource _diagnosticSource;
+        private readonly ILogger _logger;
 
         public DefaultViewComponentInvoker(
             ITypeActivatorCache typeActivatorCache,
             IViewComponentActivator viewComponentActivator,
-            DiagnosticSource diagnosticSource)
+            DiagnosticSource diagnosticSource,
+            ILogger logger)
         {
             if (typeActivatorCache == null)
             {
@@ -40,9 +44,15 @@ namespace Microsoft.AspNet.Mvc.ViewComponents
                 throw new ArgumentNullException(nameof(diagnosticSource));
             }
 
+            if (logger == null)
+            {
+                throw new ArgumentNullException(nameof(logger));
+            }
+
             _typeActivatorCache = typeActivatorCache;
             _viewComponentActivator = viewComponentActivator;
             _diagnosticSource = diagnosticSource;
+            _logger = logger;
         }
 
         public void Invoke(ViewComponentContext context)
@@ -135,15 +145,20 @@ namespace Microsoft.AspNet.Mvc.ViewComponents
 
             var component = CreateComponent(context);
 
-            _diagnosticSource.BeforeViewComponent(context, component);
+            using (_logger.ViewComponentScope(context))
+            {
+                _diagnosticSource.BeforeViewComponent(context, component);
+                _logger.ViewComponentExecuting(context);
 
-            var result = await ControllerActionExecutor.ExecuteAsync(method, component, context.Arguments);
+                var startTime = Environment.TickCount;
+                var result = await ControllerActionExecutor.ExecuteAsync(method, component, context.Arguments);
 
-            var viewComponentResult = CoerceToViewComponentResult(result);
+                var viewComponentResult = CoerceToViewComponentResult(result);
+                _logger.ViewComponentExecuted(context, startTime, viewComponentResult);
+                _diagnosticSource.AfterViewComponent(context, viewComponentResult, component);
 
-            _diagnosticSource.AfterViewComponent(context, viewComponentResult, component);
+                return viewComponentResult;
-
+            }
-            return viewComponentResult;
         }
 
         public IViewComponentResult InvokeSyncCore(MethodInfo method, ViewComponentContext context)
@@ -162,24 +177,30 @@ namespace Microsoft.AspNet.Mvc.ViewComponents
 
             object result = null;
 
-            _diagnosticSource.BeforeViewComponent(context, component);
+            using (_logger.ViewComponentScope(context))
-
-            try
             {
-                result = method.Invoke(component, context.Arguments);
+                _diagnosticSource.BeforeViewComponent(context, component);
+                _logger.ViewComponentExecuting(context);
+
+                try
+                {
+                    var startTime = Environment.TickCount;
+                    result = method.Invoke(component, context.Arguments);
+
+                    var viewComponentResult = CoerceToViewComponentResult(result);
+                    _logger.ViewComponentExecuted(context, startTime, viewComponentResult);
+                    _diagnosticSource.AfterViewComponent(context, viewComponentResult, component);
+
+                    return viewComponentResult;
+                }
+                catch (TargetInvocationException ex)
+                {
+                    // Preserve callstack of any user-thrown exceptions.
+                    var exceptionInfo = ExceptionDispatchInfo.Capture(ex.InnerException);
+                    exceptionInfo.Throw();
+                    return null; // Unreachable
+                }
             }
-            catch (TargetInvocationException ex)
-            {
-                // Preserve callstack of any user-thrown exceptions.
-                var exceptionInfo = ExceptionDispatchInfo.Capture(ex.InnerException);
-                exceptionInfo.Throw();
-            }
-
-            var viewComponentResult = CoerceToViewComponentResult(result);
-
-            _diagnosticSource.AfterViewComponent(context, viewComponentResult, component);
-
-            return viewComponentResult;
         }
 
         private static IViewComponentResult CoerceToViewComponentResult(object value)

src/Microsoft.AspNet.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvokerFactory.cs

@@ -4,6 +4,7 @@
 using System;
 using System.Diagnostics;
 using Microsoft.AspNet.Mvc.Infrastructure;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNet.Mvc.ViewComponents
 {
@@ -11,16 +12,20 @@ namespace Microsoft.AspNet.Mvc.ViewComponents
     {
         private readonly ITypeActivatorCache _typeActivatorCache;
         private readonly IViewComponentActivator _viewComponentActivator;
+        private readonly ILogger _logger;
         private readonly DiagnosticSource _diagnosticSource;
 
         public DefaultViewComponentInvokerFactory(
             ITypeActivatorCache typeActivatorCache,
             IViewComponentActivator viewComponentActivator,
-            DiagnosticSource diagnosticSource)
+            DiagnosticSource diagnosticSource,
+            ILoggerFactory loggerFactory)
         {
             _typeActivatorCache = typeActivatorCache;
             _viewComponentActivator = viewComponentActivator;
             _diagnosticSource = diagnosticSource;
+
+            _logger = loggerFactory.CreateLogger<DefaultViewComponentInvoker>();
         }
 
         /// <inheritdoc />
@@ -37,7 +42,8 @@ namespace Microsoft.AspNet.Mvc.ViewComponents
             return new DefaultViewComponentInvoker(
                 _typeActivatorCache,
                 _viewComponentActivator,
-                _diagnosticSource);
+                _diagnosticSource,
+                _logger);
         }
     }
 }

src/Microsoft.AspNet.Mvc.ViewFeatures/ViewComponents/ViewComponentDescriptor.cs

@@ -2,14 +2,52 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
+using System.Diagnostics;
 
 namespace Microsoft.AspNet.Mvc.ViewComponents
 {
     /// <summary>
     /// A descriptor for a View Component.
     /// </summary>
+    [DebuggerDisplay("{DisplayName}")]
     public class ViewComponentDescriptor
     {
+        private string _displayName;
+
+        /// <summary>
+        /// Creates a new <see cref="ViewComponentDescriptor"/>.
+        /// </summary>
+        public ViewComponentDescriptor()
+        {
+            Id = Guid.NewGuid().ToString();
+        }
+
+        /// <summary>
+        /// Gets or sets the display name of the View Component.
+        /// </summary>
+        public string DisplayName
+        {
+            get
+            {
+                if (_displayName == null)
+                {
+                    _displayName = Type?.FullName;
+                }
+
+                return _displayName;
+            }
+
+            set
+            {
+                if (value == null)
+                {
+                    throw new ArgumentNullException(nameof(value));
+                }
+
+                _displayName = value;
+            }
+        }
+
         /// <summary>
         /// Gets or sets the full name.
         /// </summary>
@@ -41,6 +79,11 @@ namespace Microsoft.AspNet.Mvc.ViewComponents
         /// </remarks>
         public string FullName { get; set; }
 
+        /// <summary>
+        /// Gets or set the generated unique identifier for this <see cref="ViewComponentDescriptor"/>.
+        /// </summary>
+        public string Id { get; set; }
+
         /// <summary>
         /// Gets or sets the short name.
         /// </summary>