#150 Handle OperationCancelledExceptions to prevent log noise

aspnet · Sep 8, 2016 · bbf1478 · bbf1478
1 parent df66f51
commit bbf1478
Show file tree

Hide file tree

Showing 15 changed files with 385 additions and 16 deletions.
diff --git a/StaticFiles.sln b/StaticFiles.sln
@@ -1,7 +1,6 @@
-
 Microsoft Visual Studio Solution File, Format Version 12.00
 # Visual Studio 14
-VisualStudioVersion = 14.0.21916.0
+VisualStudioVersion = 14.0.25420.1
 MinimumVisualStudioVersion = 10.0.40219.1
 Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "src", "src", "{40EE0889-960E-41B4-A3D3-9CE963EB0797}"
 EndProject
@@ -20,6 +19,8 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Solution Items", "Solution
 		global.json = global.json
 	EndProjectSection
 EndProject
+Project("{8BB2217D-0F2D-49D1-97BC-3654ED321F3B}") = "Microsoft.AspNetCore.StaticFiles.FunctionalTests", "test\Microsoft.AspNetCore.StaticFiles.FunctionalTests\Microsoft.AspNetCore.StaticFiles.FunctionalTests.xproj", "{FDF0539C-1F62-4B78-91B1-C687886931CA}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -60,6 +61,18 @@ Global
 		{CC87FE7D-8F42-4BE9-A152-9625E837C1E5}.Release|Mixed Platforms.ActiveCfg = Release|Any CPU
 		{CC87FE7D-8F42-4BE9-A152-9625E837C1E5}.Release|Mixed Platforms.Build.0 = Release|Any CPU
 		{CC87FE7D-8F42-4BE9-A152-9625E837C1E5}.Release|x86.ActiveCfg = Release|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Debug|Mixed Platforms.ActiveCfg = Debug|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Debug|Mixed Platforms.Build.0 = Debug|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Debug|x86.ActiveCfg = Debug|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Debug|x86.Build.0 = Debug|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Release|Any CPU.Build.0 = Release|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Release|Mixed Platforms.ActiveCfg = Release|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Release|Mixed Platforms.Build.0 = Release|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Release|x86.ActiveCfg = Release|Any CPU
+		{FDF0539C-1F62-4B78-91B1-C687886931CA}.Release|x86.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -68,5 +81,6 @@ Global
 		{8D7BC5A4-F19C-4184-8338-A6B42997218C} = {40EE0889-960E-41B4-A3D3-9CE963EB0797}
 		{092141D9-305A-4FC5-AE74-CB23982CA8D4} = {8B21A3A9-9CA6-4857-A6E0-1A3203404B60}
 		{CC87FE7D-8F42-4BE9-A152-9625E837C1E5} = {EF02AFE8-7C15-4DDB-8B2C-58A676112A98}
+		{FDF0539C-1F62-4B78-91B1-C687886931CA} = {EF02AFE8-7C15-4DDB-8B2C-58A676112A98}
 	EndGlobalSection
 EndGlobal
diff --git a/src/Microsoft.AspNetCore.StaticFiles/LoggerExtensions.cs b/src/Microsoft.AspNetCore.StaticFiles/LoggerExtensions.cs
@@ -25,6 +25,7 @@ internal static class LoggerExtensions
         private static Action<ILogger, StringValues, string, Exception> _logCopyingFileRange;
         private static Action<ILogger, long, string, string, Exception> _logCopyingBytesToResponse;
         private static Action<ILogger, string, Exception> _logMultipleFileRanges;
+        private static Action<ILogger, Exception> _logWriteCancelled;
 
         static LoggerExtensions()
         {
@@ -80,6 +81,10 @@ static LoggerExtensions()
                 logLevel: LogLevel.Warning,
                 eventId: 13,
                 formatString: "Multiple ranges are not allowed: '{Ranges}'");
+            _logWriteCancelled = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 14,
+                formatString: "The file transmission was cancelled");
         }
 
         public static void LogRequestMethodNotSupported(this ILogger logger, string method)
@@ -155,5 +160,10 @@ public static void LogMultipleFileRanges(this ILogger logger, string range)
         {
             _logMultipleFileRanges(logger, range, null);
         }
+
+        public static void LogWriteCancelled(this ILogger logger, Exception ex)
+        {
+            _logWriteCancelled(logger, ex);
+        }
     }
 }
diff --git a/src/Microsoft.AspNetCore.StaticFiles/StaticFileContext.cs b/src/Microsoft.AspNetCore.StaticFiles/StaticFileContext.cs
@@ -6,6 +6,7 @@
 using System.Diagnostics;
 using System.IO;
 using System.Linq;
+using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Builder;
 using Microsoft.AspNetCore.Http;
@@ -345,24 +346,29 @@ public Task SendStatusAsync(int statusCode)
         public async Task SendAsync()
         {
             ApplyResponseHeaders(Constants.Status200Ok);
-
             string physicalPath = _fileInfo.PhysicalPath;
             var sendFile = _context.Features.Get<IHttpSendFileFeature>();
             if (sendFile != null && !string.IsNullOrEmpty(physicalPath))
             {
-                await sendFile.SendFileAsync(physicalPath, 0, _length, _context.RequestAborted);
+                // We don't need to directly cancel this, if the client disconnects it will fail silently.
+                await sendFile.SendFileAsync(physicalPath, 0, _length, CancellationToken.None);
                 return;
             }
 
-            Stream readStream = _fileInfo.CreateReadStream();
             try
             {
-                // Larger StreamCopyBufferSize is required because in case of FileStream readStream isn't going to be buffering
-                await StreamCopyOperation.CopyToAsync(readStream, _response.Body, _length, StreamCopyBufferSize, _context.RequestAborted);
+                using (var readStream = _fileInfo.CreateReadStream())
+                {
+                    // Larger StreamCopyBufferSize is required because in case of FileStream readStream isn't going to be buffering
+                    await StreamCopyOperation.CopyToAsync(readStream, _response.Body, _length, StreamCopyBufferSize, _context.RequestAborted);
+                }
             }
-            finally
+            catch (OperationCanceledException ex)
             {
-                readStream.Dispose();
+                _logger.LogWriteCancelled(ex);
+                // Don't throw this exception, it's most likely caused by the client disconnecting.
+                // However, if it was cancelled for any other reason we need to prevent empty responses.
+                _context.Abort();
             }
         }
 
@@ -400,20 +406,26 @@ internal async Task SendRangeAsync()
             if (sendFile != null && !string.IsNullOrEmpty(physicalPath))
             {
                 _logger.LogSendingFileRange(_response.Headers[HeaderNames.ContentRange], physicalPath);
-                await sendFile.SendFileAsync(physicalPath, start, length, _context.RequestAborted);
+                // We don't need to directly cancel this, if the client disconnects it will fail silently.
+                await sendFile.SendFileAsync(physicalPath, start, length, CancellationToken.None);
                 return;
             }
 
-            Stream readStream = _fileInfo.CreateReadStream();
             try
             {
-                readStream.Seek(start, SeekOrigin.Begin); // TODO: What if !CanSeek?
-                _logger.LogCopyingFileRange(_response.Headers[HeaderNames.ContentRange], SubPath);
-                await StreamCopyOperation.CopyToAsync(readStream, _response.Body, length, _context.RequestAborted);
+                using (var readStream = _fileInfo.CreateReadStream())
+                {
+                    readStream.Seek(start, SeekOrigin.Begin); // TODO: What if !CanSeek?
+                    _logger.LogCopyingFileRange(_response.Headers[HeaderNames.ContentRange], SubPath);
+                    await StreamCopyOperation.CopyToAsync(readStream, _response.Body, length, _context.RequestAborted);
+                }
             }
-            finally
+            catch (OperationCanceledException ex)
             {
-                readStream.Dispose();
+                _logger.LogWriteCancelled(ex);
+                // Don't throw this exception, it's most likely caused by the client disconnecting.
+                // However, if it was cancelled for any other reason we need to prevent empty responses.
+                _context.Abort();
             }
         }
 

diff --git a/...etCore.StaticFiles.FunctionalTests/Microsoft.AspNetCore.StaticFiles.FunctionalTests.xproj b/...etCore.StaticFiles.FunctionalTests/Microsoft.AspNetCore.StaticFiles.FunctionalTests.xproj
@@ -0,0 +1,20 @@
+<?xml version="1.0" encoding="utf-8"?>
+<Project ToolsVersion="14.0" DefaultTargets="Build" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
+  <PropertyGroup>
+    <VisualStudioVersion Condition="'$(VisualStudioVersion)' == ''">14.0</VisualStudioVersion>
+    <VSToolsPath Condition="'$(VSToolsPath)' == ''">$(MSBuildExtensionsPath32)\Microsoft\VisualStudio\v$(VisualStudioVersion)</VSToolsPath>
+  </PropertyGroup>
+  <Import Project="$(VSToolsPath)\DNX\Microsoft.DNX.Props" Condition="'$(VSToolsPath)' != ''" />
+  <PropertyGroup Label="Globals">
+    <ProjectGuid>fdf0539c-1f62-4b78-91b1-c687886931ca</ProjectGuid>
+    <BaseIntermediateOutputPath Condition="'$(BaseIntermediateOutputPath)'=='' ">.\obj</BaseIntermediateOutputPath>
+    <OutputPath Condition="'$(OutputPath)'=='' ">.\bin\</OutputPath>
+  </PropertyGroup>
+  <PropertyGroup>
+    <SchemaVersion>2.0</SchemaVersion>
+  </PropertyGroup>
+  <ItemGroup>
+    <Service Include="{82a7f48d-3b50-4b1e-b82e-3ada8210c358}" />
+  </ItemGroup>
+  <Import Project="$(VSToolsPath)\DNX\Microsoft.DNX.targets" Condition="'$(VSToolsPath)' != ''" />
+</Project>