From 37f19b47896e346e44fe4bf14211dd2a0dae7412 Mon Sep 17 00:00:00 2001 From: Victor Hurdugaci Date: Thu, 22 Oct 2015 12:02:39 -0700 Subject: [PATCH] Improve logging and add more messages --- .../LoggerExtensions.cs | 159 ++++++++++++++++++ .../SendFileMiddleware.cs | 9 +- .../StaticFileContext.cs | 25 ++- .../StaticFileMiddleware.cs | 38 +++-- 4 files changed, 200 insertions(+), 31 deletions(-) create mode 100644 src/Microsoft.AspNet.StaticFiles/LoggerExtensions.cs diff --git a/src/Microsoft.AspNet.StaticFiles/LoggerExtensions.cs b/src/Microsoft.AspNet.StaticFiles/LoggerExtensions.cs new file mode 100644 index 0000000..d8418a4 --- /dev/null +++ b/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 +{ + /// + /// Defines *all* the logger messages produced by static files + /// + internal static class LoggerExtensions + { + private static Action _logMethodNotSupported; + private static Action _logFileServed; + private static Action _logPathMismatch; + private static Action _logFileTypeNotSupported; + private static Action _logFileNotFound; + private static Action _logPathNotModified; + private static Action _logPreconditionFailed; + private static Action _logHandled; + private static Action _logRangeNotSatisfiable; + private static Action _logSendingFileRange; + private static Action _logCopyingFileRange; + private static Action _logCopyingBytesToResponse; + private static Action _logMultipleFileRanges; + + static LoggerExtensions() + { + _logMethodNotSupported = LoggerMessage.Define( + logLevel: LogLevel.Verbose, + eventId: 1, + formatString: "{Method} requests are not supported"); + _logFileServed = LoggerMessage.Define( + logLevel: LogLevel.Information, + eventId: 2, + formatString: "Sending file. Request path: '{VirtualPath}'. Physical path: '{PhysicalPath}'"); + _logPathMismatch = LoggerMessage.Define( + logLevel: LogLevel.Verbose, + eventId: 3, + formatString: "The request path {Path} does not match the path filter"); + _logFileTypeNotSupported = LoggerMessage.Define( + logLevel: LogLevel.Verbose, + eventId: 4, + formatString: "The request path {Path} does not match a supported file type"); + _logFileNotFound = LoggerMessage.Define( + logLevel: LogLevel.Verbose, + eventId: 5, + formatString: "The request path {Path} does not match an existing file"); + _logPathNotModified = LoggerMessage.Define( + logLevel: LogLevel.Information, + eventId: 6, + formatString: "The file {Path} was not modified"); + _logPreconditionFailed = LoggerMessage.Define( + logLevel: LogLevel.Information, + eventId: 7, + formatString: "Precondition for {Path} failed"); + _logHandled = LoggerMessage.Define( + logLevel: LogLevel.Verbose, + eventId: 8, + formatString: "Handled. Status code: {StatusCode} File: {Path}"); + _logRangeNotSatisfiable = LoggerMessage.Define( + logLevel: LogLevel.Warning, + eventId: 9, + formatString: "Range not satisfiable for {Path}"); + _logSendingFileRange = LoggerMessage.Define( + logLevel: LogLevel.Information, + eventId: 10, + formatString: "Sending {Range} of file {Path}"); + _logCopyingFileRange = LoggerMessage.Define( + logLevel: LogLevel.Verbose, + eventId: 11, + formatString: "Copying {Range} of file {Path} to the response body"); + _logCopyingBytesToResponse = LoggerMessage.Define( + logLevel: LogLevel.Verbose, + eventId: 12, + formatString: "Copying bytes {Start}-{End} of file {Path} to response body"); + _logMultipleFileRanges = LoggerMessage.Define( + 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); + } + } +} diff --git a/src/Microsoft.AspNet.StaticFiles/SendFileMiddleware.cs b/src/Microsoft.AspNet.StaticFiles/SendFileMiddleware.cs index a47dc49..01c8422 100644 --- a/src/Microsoft.AspNet.StaticFiles/SendFileMiddleware.cs +++ b/src/Microsoft.AspNet.StaticFiles/SendFileMiddleware.cs @@ -103,10 +103,11 @@ public async Task SendFileAsync(string fileName, long offset, long? length, Canc try { fileStream.Seek(offset, SeekOrigin.Begin); - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.LogVerbose(string.Format("Copying bytes {0}-{1} of file {2} to response body", offset, length != null ? (offset + length).ToString() : "*", fileName)); - } + + _logger.LogCopyingBytesToResponse( + start: offset, + end: length != null ? (offset + length) : null, + path: fileName); await StreamCopyOperation.CopyToAsync(fileStream, _output, length, cancel); } finally diff --git a/src/Microsoft.AspNet.StaticFiles/StaticFileContext.cs b/src/Microsoft.AspNet.StaticFiles/StaticFileContext.cs index 31852e0..147fce5 100644 --- a/src/Microsoft.AspNet.StaticFiles/StaticFileContext.cs +++ b/src/Microsoft.AspNet.StaticFiles/StaticFileContext.cs @@ -95,6 +95,11 @@ public string SubPath get { return _subPath.Value; } } + public string PhysicalPath + { + get { return _fileInfo?.PhysicalPath; } + } + public bool ValidateMethod() { _method = _request.Method; @@ -226,7 +231,7 @@ private void ComputeRange() // 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 @@ public Task SendStatusAsync(int statusCode) { ApplyResponseHeaders(statusCode); - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.LogVerbose(string.Format("Handled. Status code: {0} File: {1}", statusCode, SubPath)); - } + _logger.LogHandled(statusCode, SubPath); return Constants.CompletedTask; } @@ -358,7 +360,8 @@ internal async Task SendRangeAsync() // 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 @@ internal async Task SendRangeAsync() var sendFile = _context.Features.Get(); if (sendFile != null && !string.IsNullOrEmpty(physicalPath)) { - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.LogVerbose(string.Format("Sending {0} of file {1}", _response.Headers[HeaderNames.ContentRange], physicalPath)); - } + _logger.LogSendingFileRange(_response.Headers[HeaderNames.ContentRange], physicalPath); await sendFile.SendFileAsync(physicalPath, start, length, _context.RequestAborted); return; } @@ -386,10 +386,7 @@ internal async Task SendRangeAsync() try { readStream.Seek(start, SeekOrigin.Begin); // TODO: What if !CanSeek? - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.LogVerbose(string.Format("Copying {0} of file {1} to the response body", _response.Headers[HeaderNames.ContentRange], SubPath)); - } + _logger.LogCopyingFileRange(_response.Headers[HeaderNames.ContentRange], SubPath); await StreamCopyOperation.CopyToAsync(readStream, _response.Body, length, _context.RequestAborted); } finally diff --git a/src/Microsoft.AspNet.StaticFiles/StaticFileMiddleware.cs b/src/Microsoft.AspNet.StaticFiles/StaticFileMiddleware.cs index c5d42b5..e5818f1 100644 --- a/src/Microsoft.AspNet.StaticFiles/StaticFileMiddleware.cs +++ b/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 @@ public StaticFileMiddleware(RequestDelegate next, IHostingEnvironment hostingEnv public Task Invoke(HttpContext context) { var fileContext = new StaticFileContext(context, _options, _matchUrl, _logger); - if (fileContext.ValidateMethod() - && fileContext.ValidatePath() - && fileContext.LookupContentType() - && fileContext.LookupFileInfo()) + + if (!fileContext.ValidateMethod()) { + _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 @@ public Task Invoke(HttpContext context) { return fileContext.SendRangeAsync(); } - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.LogVerbose(string.Format("Copying file {0} to the response body", fileContext.SubPath)); - } + + _logger.LogFileServed(fileContext.SubPath, fileContext.PhysicalPath); return fileContext.SendAsync(); case StaticFileContext.PreconditionState.NotModified: - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.LogVerbose(string.Format("{0} not modified", fileContext.SubPath)); - } + _logger.LogPathNotModified(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; } }