#150 Handle OperationCancelledExceptions to prevent log noise

This commit is contained in:
Chris R 2016-08-29 09:49:17 -07:00
parent df66f51f46
commit bbf1478821
15 changed files with 385 additions and 16 deletions

View File

@ -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

View File

@ -25,6 +25,7 @@ namespace Microsoft.AspNetCore.StaticFiles
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 @@ namespace Microsoft.AspNetCore.StaticFiles
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 @@ namespace Microsoft.AspNetCore.StaticFiles
{
_logMultipleFileRanges(logger, range, null);
}
public static void LogWriteCancelled(this ILogger logger, Exception ex)
{
_logWriteCancelled(logger, ex);
}
}
}

View File

@ -6,6 +6,7 @@ using System.Collections.Generic;
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 @@ namespace Microsoft.AspNetCore.StaticFiles
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 @@ namespace Microsoft.AspNetCore.StaticFiles
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();
}
}

View File

@ -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>

View File

@ -0,0 +1,247 @@
// 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 System.IO;
using System.Linq;
using System.Net;
using System.Net.Http;
using System.Net.Sockets;
using System.Text;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Server.IntegrationTesting;
using Microsoft.AspNetCore.Testing.xunit;
using Microsoft.Extensions.DependencyInjection;
using Xunit;
namespace Microsoft.AspNetCore.StaticFiles
{
public class StaticFileMiddlewareTests
{
[Fact]
public async Task ReturnsNotFoundWithoutWwwroot()
{
var baseAddress = "http://localhost:12345";
var builder = new WebHostBuilder()
.UseKestrel()
.Configure(app => app.UseStaticFiles());
using (var server = builder.Start(baseAddress))
{
using (var client = new HttpClient() { BaseAddress = new Uri(baseAddress) })
{
var response = await client.GetAsync("TestDocument.txt");
Assert.Equal(HttpStatusCode.NotFound, response.StatusCode);
}
}
}
[Fact]
public async Task FoundFile_LastModifiedTrimsSeconds()
{
var baseAddress = "http://localhost:12345";
var builder = new WebHostBuilder()
.UseKestrel()
.UseWebRoot(Directory.GetCurrentDirectory())
.Configure(app => app.UseStaticFiles());
using (var server = builder.Start(baseAddress))
{
using (var client = new HttpClient() { BaseAddress = new Uri(baseAddress) })
{
var last = File.GetLastWriteTimeUtc("TestDocument.txt");
var response = await client.GetAsync("TestDocument.txt");
var trimed = new DateTimeOffset(last.Year, last.Month, last.Day, last.Hour, last.Minute, last.Second, TimeSpan.Zero).ToUniversalTime();
Assert.Equal(response.Content.Headers.LastModified.Value, trimed);
}
}
}
[Theory]
[MemberData(nameof(ExistingFiles))]
public async Task FoundFile_Served_All(string baseUrl, string baseDir, string requestUrl)
{
await FoundFile_Served(baseUrl, baseDir, requestUrl);
}
[ConditionalTheory]
[OSSkipCondition(OperatingSystems.Linux)]
[OSSkipCondition(OperatingSystems.MacOSX)]
[InlineData("", @".", "/testDocument.Txt")]
[InlineData("/somedir", @".", "/somedir/Testdocument.TXT")]
[InlineData("/SomeDir", @".", "/soMediR/testdocument.txT")]
[InlineData("/somedir", @"SubFolder", "/somedir/Ranges.tXt")]
public async Task FoundFile_Served_Windows(string baseUrl, string baseDir, string requestUrl)
{
await FoundFile_Served(baseUrl, baseDir, requestUrl);
}
public async Task FoundFile_Served(string baseUrl, string baseDir, string requestUrl)
{
var baseAddress = "http://localhost:12345";
var builder = new WebHostBuilder()
.UseKestrel()
.UseWebRoot(Path.Combine(Directory.GetCurrentDirectory(), baseDir))
.Configure(app => app.UseStaticFiles(new StaticFileOptions()
{
RequestPath = new PathString(baseUrl),
}));
using (var server = builder.Start(baseAddress))
{
var hostingEnvironment = server.Services.GetService<IHostingEnvironment>();
using (var client = new HttpClient() { BaseAddress = new Uri(baseAddress) })
{
var fileInfo = hostingEnvironment.WebRootFileProvider.GetFileInfo(Path.GetFileName(requestUrl));
var response = await client.GetAsync(requestUrl);
var responseContent = await response.Content.ReadAsByteArrayAsync();
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
Assert.Equal("text/plain", response.Content.Headers.ContentType.ToString());
Assert.True(response.Content.Headers.ContentLength == fileInfo.Length);
Assert.Equal(response.Content.Headers.ContentLength, responseContent.Length);
using (var stream = fileInfo.CreateReadStream())
{
var fileContents = new byte[stream.Length];
stream.Read(fileContents, 0, (int)stream.Length);
Assert.True(responseContent.SequenceEqual(fileContents));
}
}
}
}
[Theory]
[MemberData(nameof(ExistingFiles))]
public async Task HeadFile_HeadersButNotBodyServed(string baseUrl, string baseDir, string requestUrl)
{
var baseAddress = "http://localhost:12345";
var builder = new WebHostBuilder()
.UseKestrel()
.UseWebRoot(Path.Combine(Directory.GetCurrentDirectory(), baseDir))
.Configure(app => app.UseStaticFiles(new StaticFileOptions()
{
RequestPath = new PathString(baseUrl),
}));
using (var server = builder.Start(baseAddress))
{
var hostingEnvironment = server.Services.GetService<IHostingEnvironment>();
using (var client = new HttpClient() { BaseAddress = new Uri(baseAddress) })
{
var fileInfo = hostingEnvironment.WebRootFileProvider.GetFileInfo(Path.GetFileName(requestUrl));
var request = new HttpRequestMessage(HttpMethod.Head, requestUrl);
var response = await client.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
Assert.Equal("text/plain", response.Content.Headers.ContentType.ToString());
Assert.True(response.Content.Headers.ContentLength == fileInfo.Length);
Assert.Equal(0, (await response.Content.ReadAsByteArrayAsync()).Length);
}
}
}
public static IEnumerable<string[]> ExistingFiles => new[]
{
new[] {"", @".", "/TestDocument.txt"},
new[] {"/somedir", @".", "/somedir/TestDocument.txt"},
new[] {"/SomeDir", @".", "/soMediR/TestDocument.txt"},
new[] {"", @"SubFolder", "/ranges.txt"},
new[] {"/somedir", @"SubFolder", "/somedir/ranges.txt"},
new[] {"", @"SubFolder", "/Empty.txt"}
};
[Fact]
public void ClientDisconnect_Kestrel_NoWriteExceptionThrown()
{
ClientDisconnect_NoWriteExceptionThrown(ServerType.Kestrel);
}
[ConditionalFact]
[OSSkipCondition(OperatingSystems.Linux)]
[OSSkipCondition(OperatingSystems.MacOSX)]
public void ClientDisconnect_WebListener_NoWriteExceptionThrown()
{
ClientDisconnect_NoWriteExceptionThrown(ServerType.WebListener);
}
public void ClientDisconnect_NoWriteExceptionThrown(ServerType serverType)
{
var interval = TimeSpan.FromSeconds(15);
var baseAddress = "http://localhost:12345";
var requestReceived = new ManualResetEvent(false);
var requestCacelled = new ManualResetEvent(false);
var responseComplete = new ManualResetEvent(false);
Exception exception = null;
var builder = new WebHostBuilder()
.UseWebRoot(Path.Combine(Directory.GetCurrentDirectory()))
.Configure(app =>
{
app.Use(async (context, next) =>
{
try
{
requestReceived.Set();
Assert.True(requestCacelled.WaitOne(interval), "not cancelled");
Assert.True(context.RequestAborted.WaitHandle.WaitOne(interval), "not aborted");
await next();
}
catch (Exception ex)
{
exception = ex;
}
responseComplete.Set();
});
app.UseStaticFiles();
});
if (serverType == ServerType.WebListener)
{
builder.UseWebListener();
}
else if (serverType == ServerType.Kestrel)
{
builder.UseKestrel();
}
using (var server = builder.Start(baseAddress))
{
// We don't use HttpClient here because it's disconnect behavior varies across platforms.
var socket = SendSocketRequestAsync(baseAddress, "/TestDocument1MB.txt");
Assert.True(requestReceived.WaitOne(interval), "not received");
socket.LingerState = new LingerOption(true, 0);
socket.Dispose();
requestCacelled.Set();
Assert.True(responseComplete.WaitOne(interval), "not completed");
Assert.Null(exception);
}
}
private Socket SendSocketRequestAsync(string address, string path, string method = "GET")
{
var uri = new Uri(address);
var builder = new StringBuilder();
builder.Append($"{method} {path} HTTP/1.1\r\n");
builder.Append($"HOST: {uri.Authority}\r\n\r\n");
byte[] request = Encoding.ASCII.GetBytes(builder.ToString());
var socket = new Socket(SocketType.Stream, ProtocolType.Tcp);
socket.Connect(IPAddress.Loopback, uri.Port);
socket.Send(request);
return socket;
}
}
}

View File

@ -0,0 +1,11 @@
<!DOCTYPE html>
<html lang="en" xmlns="http://www.w3.org/1999/xhtml">
<head>
<meta charset="utf-8" />
<title></title>
</head>
<body>
Hello World
</body>
</html>

View File

@ -0,0 +1 @@
<xml/>

View File

@ -0,0 +1 @@
0123456789abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ

View File

@ -0,0 +1 @@
0123456789abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ

File diff suppressed because one or more lines are too long

View File

@ -0,0 +1,46 @@
{
"buildOptions": {
"warningsAsErrors": true,
"keyFile": "../../tools/Key.snk",
"copyToOutput": {
"include": [
"SubFolder/**/*",
"TestDocument.txt",
"TestDocument1MB.txt"
]
}
},
"publishOptions": {
"include": [
"SubFolder/**/*",
"TestDocument.txt"
]
},
"dependencies": {
"System.Runtime.InteropServices.RuntimeInformation": "4.0.0-*",
"dotnet-test-xunit": "2.2.0-*",
"Microsoft.AspNetCore.StaticFiles": "1.1.0-*",
"Microsoft.AspNetCore.Server.Kestrel": "1.1.0-*",
"Microsoft.AspNetCore.Server.WebListener": "0.2.0-*",
"Microsoft.AspNetCore.Testing": "1.1.0-*",
"Microsoft.AspNetCore.Server.IntegrationTesting": "0.2.0-*",
"Microsoft.Extensions.Logging.Testing": "1.1.0-*",
"xunit": "2.2.0-*"
},
"frameworks": {
"netcoreapp1.0": {
"dependencies": {
"Microsoft.NETCore.App": {
"version": "1.0.0-*",
"type": "platform"
}
}
},
"net451": {
"frameworkAssemblies": {
"System.Net.Http": ""
}
}
},
"testRunner": "xunit"
}

View File

@ -13,5 +13,8 @@
<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>

View File

@ -31,6 +31,7 @@ namespace Microsoft.AspNetCore.StaticFiles
Assert.Equal(HttpStatusCode.NotFound, response.StatusCode);
}
[Fact]
public async Task FoundFile_LastModifiedTrimsSeconds()
{
using (var fileProvider = new PhysicalFileProvider(Directory.GetCurrentDirectory()))