Improve logging and add more messages

src/Microsoft.AspNet.StaticFiles/LoggerExtensions.cs

@@ -0,0 +1,159 @@
+// 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;
+using Microsoft.Extensions.Primitives;
+
+namespace Microsoft.AspNet.StaticFiles
+{
+    /// <summary>
+    /// Defines *all* the logger messages produced by static files
+    /// </summary>
+    internal static class LoggerExtensions
+    {
+        private static Action<ILogger, string, Exception> _logMethodNotSupported;
+        private static Action<ILogger, string, string, Exception> _logFileServed;
+        private static Action<ILogger, string, Exception> _logPathMismatch;
+        private static Action<ILogger, string, Exception> _logFileTypeNotSupported;
+        private static Action<ILogger, string, Exception> _logFileNotFound;
+        private static Action<ILogger, string, Exception> _logPathNotModified;
+        private static Action<ILogger, string, Exception> _logPreconditionFailed;
+        private static Action<ILogger, int, string, Exception> _logHandled;
+        private static Action<ILogger, string, Exception> _logRangeNotSatisfiable;
+        private static Action<ILogger, StringValues, string, Exception> _logSendingFileRange;
+        private static Action<ILogger, StringValues, string, Exception> _logCopyingFileRange;
+        private static Action<ILogger, long, string, string, Exception> _logCopyingBytesToResponse;
+        private static Action<ILogger, string, Exception> _logMultipleFileRanges;
+
+        static LoggerExtensions()
+        {
+            _logMethodNotSupported = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Verbose,
+                eventId: 1,
+                formatString: "{Method} requests are not supported");
+            _logFileServed = LoggerMessage.Define<string, string>(
+               logLevel: LogLevel.Information,
+               eventId: 2,
+               formatString: "Sending file. Request path: '{VirtualPath}'. Physical path: '{PhysicalPath}'");
+            _logPathMismatch = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Verbose,
+                eventId: 3,
+                formatString: "The request path {Path} does not match the path filter");
+            _logFileTypeNotSupported = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Verbose,
+                eventId: 4,
+                formatString: "The request path {Path} does not match a supported file type");
+            _logFileNotFound = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Verbose,
+                eventId: 5,
+                formatString: "The request path {Path} does not match an existing file");
+            _logPathNotModified = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Information,
+                eventId: 6,
+                formatString: "The file {Path} was not modified");
+            _logPreconditionFailed = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Information,
+                eventId: 7,
+                formatString: "Precondition for {Path} failed");
+            _logHandled = LoggerMessage.Define<int, string>(
+                logLevel: LogLevel.Verbose,
+                eventId: 8,
+                formatString: "Handled. Status code: {StatusCode} File: {Path}");
+            _logRangeNotSatisfiable = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Warning,
+                eventId: 9,
+                formatString: "Range not satisfiable for {Path}");
+            _logSendingFileRange = LoggerMessage.Define<StringValues, string>(
+                logLevel: LogLevel.Information,
+                eventId: 10,
+                formatString: "Sending {Range} of file {Path}");
+            _logCopyingFileRange = LoggerMessage.Define<StringValues, string>(
+                logLevel: LogLevel.Verbose,
+                eventId: 11,
+                formatString: "Copying {Range} of file {Path} to the response body");
+            _logCopyingBytesToResponse = LoggerMessage.Define<long, string, string>(
+                logLevel: LogLevel.Verbose,
+                eventId: 12,
+                formatString: "Copying bytes {Start}-{End} of file {Path} to response body");
+            _logMultipleFileRanges = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Warning,
+                eventId: 13,
+                formatString: "Multiple ranges are not allowed: '{Ranges}'");
+        }
+
+        public static void LogRequestMethodNotSupported(this ILogger logger, string method)
+        {
+            _logMethodNotSupported(logger, method, null);
+        }
+
+        public static void LogFileServed(this ILogger logger, string virtualPath, string physicalPath)
+        {
+            if (string.IsNullOrEmpty(physicalPath))
+            {
+                physicalPath = "N/A";
+            }
+            _logFileServed(logger, virtualPath, physicalPath, null);
+        }
+
+        public static void LogPathMismatch(this ILogger logger, string path)
+        {
+            _logPathMismatch(logger, path, null);
+        }
+
+        public static void LogFileTypeNotSupported(this ILogger logger, string path)
+        {
+            _logFileTypeNotSupported(logger, path, null);
+        }
+
+        public static void LogFileNotFound(this ILogger logger, string path)
+        {
+            _logFileNotFound(logger, path, null);
+        }
+
+        public static void LogPathNotModified(this ILogger logger, string path)
+        {
+            _logPathNotModified(logger, path, null);
+        }
+
+        public static void LogPreconditionFailed(this ILogger logger, string path)
+        {
+            _logPreconditionFailed(logger, path, null);
+        }
+
+        public static void LogHandled(this ILogger logger, int statusCode, string path)
+        {
+            _logHandled(logger, statusCode, path, null);
+        }
+
+        public static void LogRangeNotSatisfiable(this ILogger logger, string path)
+        {
+            _logRangeNotSatisfiable(logger, path, null);
+        }
+
+        public static void LogSendingFileRange(this ILogger logger, StringValues range, string path)
+        {
+            _logSendingFileRange(logger, range, path, null);
+        }
+
+        public static void LogCopyingFileRange(this ILogger logger, StringValues range, string path)
+        {
+            _logCopyingFileRange(logger, range, path, null);
+        }
+
+        public static void LogCopyingBytesToResponse(this ILogger logger, long start, long? end, string path)
+        {
+            _logCopyingBytesToResponse(
+                logger,
+                start,
+                end != null ? end.ToString() : "*",
+                path,
+                null);
+        }
+
+        public static void LogMultipleFileRanges(this ILogger logger, string range)
+        {
+            _logMultipleFileRanges(logger, range, null);
+        }
+    }
+}

src/Microsoft.AspNet.StaticFiles/SendFileMiddleware.cs

@@ -103,10 +103,11 @@ namespace Microsoft.AspNet.StaticFiles
                 try
                 {
                     fileStream.Seek(offset, SeekOrigin.Begin);
-                    if (_logger.IsEnabled(LogLevel.Verbose))
+
-                    {
+                    _logger.LogCopyingBytesToResponse(
-                        _logger.LogVerbose(string.Format("Copying bytes {0}-{1} of file {2} to response body", offset, length != null ? (offset + length).ToString() : "*", fileName));
+                        start: offset,
-                    }
+                        end: length != null ? (offset + length) : null,
+                        path: fileName);
                     await StreamCopyOperation.CopyToAsync(fileStream, _output, length, cancel);
                 }
                 finally

src/Microsoft.AspNet.StaticFiles/StaticFileContext.cs

@@ -95,6 +95,11 @@ namespace Microsoft.AspNet.StaticFiles
             get { return _subPath.Value; }
         }
 
+        public string PhysicalPath
+        {
+            get { return _fileInfo?.PhysicalPath; }
+        }
+
         public bool ValidateMethod()
         {
             _method = _request.Method;
@@ -226,7 +231,7 @@ namespace Microsoft.AspNet.StaticFiles
                 // The spec allows for multiple ranges but we choose not to support them because the client may request
                 // very strange ranges (e.g. each byte separately, overlapping ranges, etc.) that could negatively
                 // impact the server. Ignore the header and serve the response normally.
-                _logger.LogWarning("Multiple ranges are not allowed: '{0}'", rangeHeader.ToString());
+                _logger.LogMultipleFileRanges(rangeHeader.ToString());
                 return;
             }
 
@@ -312,10 +317,7 @@ namespace Microsoft.AspNet.StaticFiles
         {
             ApplyResponseHeaders(statusCode);
 
-            if (_logger.IsEnabled(LogLevel.Verbose))
+            _logger.LogHandled(statusCode, SubPath);
-            {
-                _logger.LogVerbose(string.Format("Handled. Status code: {0} File: {1}", statusCode, SubPath));
-            }
             return Constants.CompletedTask;
         }
 
@@ -358,7 +360,8 @@ namespace Microsoft.AspNet.StaticFiles
                 // the current length of the selected resource.  e.g. */length
                 _responseHeaders.ContentRange = new ContentRangeHeaderValue(_length);
                 ApplyResponseHeaders(Constants.Status416RangeNotSatisfiable);
-                _logger.LogWarning("Range not satisfiable for {0}", SubPath);
+
+                _logger.LogRangeNotSatisfiable(SubPath);
                 return;
             }
 
@@ -374,10 +377,7 @@ namespace Microsoft.AspNet.StaticFiles
             var sendFile = _context.Features.Get<IHttpSendFileFeature>();
             if (sendFile != null && !string.IsNullOrEmpty(physicalPath))
             {
-                if (_logger.IsEnabled(LogLevel.Verbose))
+                _logger.LogSendingFileRange(_response.Headers[HeaderNames.ContentRange], physicalPath);
-                {
-                    _logger.LogVerbose(string.Format("Sending {0} of file {1}", _response.Headers[HeaderNames.ContentRange], physicalPath));
-                }
                 await sendFile.SendFileAsync(physicalPath, start, length, _context.RequestAborted);
                 return;
             }
@@ -386,10 +386,7 @@ namespace Microsoft.AspNet.StaticFiles
             try
             {
                 readStream.Seek(start, SeekOrigin.Begin); // TODO: What if !CanSeek?
-                if (_logger.IsEnabled(LogLevel.Verbose))
+                _logger.LogCopyingFileRange(_response.Headers[HeaderNames.ContentRange], SubPath);
-                {
-                    _logger.LogVerbose(string.Format("Copying {0} of file {1} to the response body", _response.Headers[HeaderNames.ContentRange], SubPath));
-                }
                 await StreamCopyOperation.CopyToAsync(readStream, _response.Body, length, _context.RequestAborted);
             }
             finally

src/Microsoft.AspNet.StaticFiles/StaticFileMiddleware.cs

@@ -2,6 +2,7 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
+using System.Diagnostics;
 using System.Threading.Tasks;
 using Microsoft.AspNet.Builder;
 using Microsoft.AspNet.Hosting;
@@ -68,11 +69,26 @@ namespace Microsoft.AspNet.StaticFiles
         public Task Invoke(HttpContext context)
         {
             var fileContext = new StaticFileContext(context, _options, _matchUrl, _logger);
-            if (fileContext.ValidateMethod()
+          
-                && fileContext.ValidatePath()
+            if (!fileContext.ValidateMethod())
-                && fileContext.LookupContentType()
-                && fileContext.LookupFileInfo())
             {
+                _logger.LogRequestMethodNotSupported(context.Request.Method);
+            }
+            else if (!fileContext.ValidatePath())
+            {
+                _logger.LogPathMismatch(fileContext.SubPath);
+            }
+            else if (!fileContext.LookupContentType())
+            {
+                _logger.LogFileTypeNotSupported(fileContext.SubPath);
+            }
+            else if (!fileContext.LookupFileInfo())
+            {
+                _logger.LogFileNotFound(fileContext.SubPath);
+            }
+            else
+            { 
+                // If we get here, we can try to serve the file
                 fileContext.ComprehendRequestHeaders();
 
                 switch (fileContext.GetPreconditionState())
@@ -87,25 +103,21 @@ namespace Microsoft.AspNet.StaticFiles
                         {
                             return fileContext.SendRangeAsync();
                         }
-                        if (_logger.IsEnabled(LogLevel.Verbose))
+                        
-                        {
+                        _logger.LogFileServed(fileContext.SubPath, fileContext.PhysicalPath);
-                            _logger.LogVerbose(string.Format("Copying file {0} to the response body", fileContext.SubPath));
-                        }
                         return fileContext.SendAsync();
 
                     case StaticFileContext.PreconditionState.NotModified:
-                        if (_logger.IsEnabled(LogLevel.Verbose))
+                        _logger.LogPathNotModified(fileContext.SubPath);
-                        {
-                            _logger.LogVerbose(string.Format("{0} not modified", fileContext.SubPath));
-                        }
                         return fileContext.SendStatusAsync(Constants.Status304NotModified);
 
                     case StaticFileContext.PreconditionState.PreconditionFailed:
+                        _logger.LogPreconditionFailed(fileContext.SubPath);
                         return fileContext.SendStatusAsync(Constants.Status412PreconditionFailed);
 
                     default:
                         var exception = new NotImplementedException(fileContext.GetPreconditionState().ToString());
-                        _logger.LogError("No precondition state specified", exception);
+                        Debug.Fail(exception.ToString());
                         throw exception;
                 }
             }