Add more FREB events/ tests for FREB events (#1461)

This commit is contained in:
Justin Kotalik 2018-10-09 10:25:12 -07:00 committed by GitHub
parent 1be7cd1f74
commit 23db53eae6
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
14 changed files with 1116 additions and 334 deletions

View File

@ -186,12 +186,28 @@ class ANCMWinHttpCallBack:ANCM_Events
};
[Dynamic,
Description("Inprocess executing request failure") : amended,
EventType(7),
EventLevel(2),
EventTypeName("ANCM_EXECUTE_REQUEST_FAIL") : amended
Description("Starting inprocess execute request") : amended,
EventType(8),
EventLevel(4),
EventTypeName("ANCM_INPROC_EXECUTE_REQUEST_START") : amended
]
class ANCMExecuteFailed:ANCM_Events
class ANCMExecuteStart:ANCM_Events
{
[WmiDataId(1),
Description("Context ID") : amended,
extension("Guid"),
ActivityID,
read]
object ContextId;
};
[Dynamic,
Description("Ending inprocess execute request") : amended,
EventType(10),
EventLevel(5),
EventTypeName("ANCM_INPROC_EXECUTE_REQUEST_COMPLETION") : amended
]
class ANCMExecuteEnd:ANCM_Events
{
[WmiDataId(1),
Description("Context ID") : amended,
@ -200,9 +216,93 @@ class ANCMExecuteFailed:ANCM_Events
read]
object ContextId;
[WmiDataId(2),
Description("InternetStatus") : amended,
format("x"),
Description("Notification status") : amended,
format("d"),
read]
uint32 ErrorCode;
uint32 requestStatus;
};
[Dynamic,
Description("Starting inprocess async completion") : amended,
EventType(8),
EventLevel(5),
EventTypeName("ANCM_INPROC_ASYNC_COMPLETION_START") : amended
]
class ANCMAsyncStart:ANCM_Events
{
[WmiDataId(1),
Description("Context ID") : amended,
extension("Guid"),
ActivityID,
read]
object ContextId;
};
[Dynamic,
Description("Ending inprocess async completion") : amended,
EventType(10),
EventLevel(5),
EventTypeName("ANCM_INPROC_ASYNC_COMPLETION_COMPLETION") : amended
]
class ANCMAsyncEnd:ANCM_Events
{
[WmiDataId(1),
Description("Context ID") : amended,
extension("Guid"),
ActivityID,
read]
object ContextId;
[WmiDataId(2),
Description("Notification status") : amended,
format("d"),
read]
uint32 requestStatus;
};
[Dynamic,
Description("Inprocess app shutdown") : amended,
EventType(11),
EventLevel(4),
EventTypeName("ANCM_INPROC_REQUEST_SHUTDOWN") : amended
]
class ANCMRequestShutdown:ANCM_Events
{
[WmiDataId(1),
Description("Context ID") : amended,
extension("Guid"),
ActivityID,
read]
object ContextId;
};
[Dynamic,
Description("Inprocess request disconnect") : amended,
EventType(12),
EventLevel(4),
EventTypeName("ANCM_INPROC_REQUEST_DISCONNECT") : amended
]
class ANCMRequestDisconnect:ANCM_Events
{
[WmiDataId(1),
Description("Context ID") : amended,
extension("Guid"),
ActivityID,
read]
object ContextId;
};
[Dynamic,
Description("Indicate managed request complete") : amended,
EventType(12),
EventLevel(4),
EventTypeName("ANCM_INPROC_MANAGED_REQUEST_COMPLETION") : amended
]
class ANCMManagedRequestCompletion:ANCM_Events
{
[WmiDataId(1),
Description("Context ID") : amended,
extension("Guid"),
ActivityID,
read]
object ContextId;
};

View File

@ -219,7 +219,8 @@
<ClInclude Include="IOutputManager.h" />
<ClInclude Include="irequesthandler.h" />
<ClInclude Include="LoggingHelpers.h" />
<ClInclude Include="ModuleHelpers.h" />
<ClInclude Include="ModuleHelpers.h" />
<ClInclude Include="ModuleTracer.h" />
<ClInclude Include="NonCopyable.h" />
<ClInclude Include="NullOutputManager.h" />
<ClInclude Include="PipeOutputManager.h" />

View File

@ -0,0 +1,98 @@
// Copyright (c) .NET Foundation and contributors. All rights reserved.
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
#pragma once
#include "aspnetcore_event.h"
class ModuleTracer
{
public:
ModuleTracer(IHttpTraceContext* traceContext)
{
m_traceContext = traceContext;
}
VOID
ExecuteRequestStart()
{
if (ANCMEvents::ANCM_INPROC_EXECUTE_REQUEST_START::IsEnabled(m_traceContext))
{
ANCMEvents::ANCM_INPROC_EXECUTE_REQUEST_START::RaiseEvent(
m_traceContext,
NULL);
}
}
VOID
ExecuteRequestEnd(REQUEST_NOTIFICATION_STATUS status)
{
if (ANCMEvents::ANCM_INPROC_EXECUTE_REQUEST_COMPLETION::IsEnabled(m_traceContext))
{
ANCMEvents::ANCM_INPROC_EXECUTE_REQUEST_COMPLETION::RaiseEvent(
m_traceContext,
NULL,
status);
}
}
VOID
AsyncCompletionStart()
{
if (ANCMEvents::ANCM_INPROC_ASYNC_COMPLETION_START::IsEnabled(m_traceContext))
{
ANCMEvents::ANCM_INPROC_ASYNC_COMPLETION_START::RaiseEvent(
m_traceContext,
NULL);
}
}
VOID
AsyncCompletionEnd(REQUEST_NOTIFICATION_STATUS status)
{
if (ANCMEvents::ANCM_INPROC_ASYNC_COMPLETION_COMPLETION::IsEnabled(m_traceContext))
{
ANCMEvents::ANCM_INPROC_ASYNC_COMPLETION_COMPLETION::RaiseEvent(
m_traceContext,
NULL,
status);
}
}
VOID
RequestShutdown()
{
if (ANCMEvents::ANCM_INPROC_REQUEST_SHUTDOWN::IsEnabled(m_traceContext))
{
ANCMEvents::ANCM_INPROC_REQUEST_SHUTDOWN::RaiseEvent(
m_traceContext,
NULL);
}
}
VOID
RequestDisconnect()
{
if (ANCMEvents::ANCM_INPROC_REQUEST_DISCONNECT::IsEnabled(m_traceContext))
{
ANCMEvents::ANCM_INPROC_REQUEST_DISCONNECT::RaiseEvent(
m_traceContext,
NULL);
}
}
VOID
ManagedCompletion()
{
if (ANCMEvents::ANCM_INPROC_MANAGED_REQUEST_COMPLETION::IsEnabled(m_traceContext))
{
ANCMEvents::ANCM_INPROC_MANAGED_REQUEST_COMPLETION::RaiseEvent(
m_traceContext,
NULL);
}
}
private:
IHttpTraceContext * m_traceContext;
};

File diff suppressed because it is too large Load Diff

View File

@ -35,7 +35,7 @@
<fieldset>
<h4>
For more information visit:
<a href="https://go.microsoft.com/fwlink/?LinkID =808681"> <cite> https://go.microsoft.com/fwlink/?LinkID=808681 </cite></a>
<a href="https://go.microsoft.com/fwlink/?LinkID=808681"> <cite> https://go.microsoft.com/fwlink/?LinkID=808681 </cite></a>
</h4>
</fieldset>
</div>

View File

@ -17,6 +17,7 @@
#include "WebConfigConfigurationSource.h"
#include "ConfigurationLoadException.h"
#include "StartupExceptionApplication.h"
#include "aspnetcore_event.h"
DECLARE_DEBUG_PRINT_OBJECT("aspnetcorev2_inprocess.dll");

View File

@ -3,10 +3,10 @@
#include "inprocesshandler.h"
#include "inprocessapplication.h"
#include "aspnetcore_event.h"
#include "IOutputManager.h"
#include "ShuttingDownApplication.h"
#include "ntassert.h"
#include "ModuleTracer.h"
ALLOC_CACHE_HANDLER * IN_PROCESS_HANDLER::sm_pAlloc = NULL;
@ -25,7 +25,8 @@ IN_PROCESS_HANDLER::IN_PROCESS_HANDLER(
m_pRequestHandler(pRequestHandler),
m_pRequestHandlerContext(pRequestHandlerContext),
m_pAsyncCompletionHandler(pAsyncCompletion),
m_pDisconnectHandler(pDisconnectHandler)
m_pDisconnectHandler(pDisconnectHandler),
m_moduleTracer(pW3Context->GetTraceContext())
{
}
@ -34,32 +35,11 @@ REQUEST_NOTIFICATION_STATUS
IN_PROCESS_HANDLER::OnExecuteRequestHandler()
{
// FREB log
if (ANCMEvents::ANCM_START_APPLICATION_SUCCESS::IsEnabled(m_pW3Context->GetTraceContext()))
{
ANCMEvents::ANCM_START_APPLICATION_SUCCESS::RaiseEvent(
m_pW3Context->GetTraceContext(),
NULL,
L"InProcess Application");
}
m_moduleTracer.ExecuteRequestStart();
if (m_pRequestHandler == NULL)
{
//
// return error as the application did not register callback
//
if (ANCMEvents::ANCM_EXECUTE_REQUEST_FAIL::IsEnabled(m_pW3Context->GetTraceContext()))
{
ANCMEvents::ANCM_EXECUTE_REQUEST_FAIL::RaiseEvent(m_pW3Context->GetTraceContext(),
NULL,
(ULONG)E_APPLICATION_ACTIVATION_EXEC_FAILURE);
}
m_pW3Context->GetResponse()->SetStatus(500,
"Internal Server Error",
0,
(ULONG)E_APPLICATION_ACTIVATION_EXEC_FAILURE);
m_moduleTracer.ExecuteRequestEnd(RQ_NOTIFICATION_FINISH_REQUEST);
return RQ_NOTIFICATION_FINISH_REQUEST;
}
else if (m_pApplication->QueryBlockCallbacksIntoManaged())
@ -67,7 +47,9 @@ IN_PROCESS_HANDLER::OnExecuteRequestHandler()
return ServerShutdownMessage();
}
return m_pRequestHandler(this, m_pRequestHandlerContext);
auto status = m_pRequestHandler(this, m_pRequestHandlerContext);
m_moduleTracer.ExecuteRequestEnd(status);
return status;
}
__override
@ -77,10 +59,13 @@ IN_PROCESS_HANDLER::OnAsyncCompletion(
HRESULT hrCompletionStatus
)
{
m_moduleTracer.AsyncCompletionStart();
if (m_fManagedRequestComplete)
{
// means PostCompletion has been called and this is the associated callback.
return m_requestNotificationStatus;
m_moduleTracer.AsyncCompletionEnd(m_requestNotificationStatus);
return m_requestNotificationStatus;
}
if (m_pApplication->QueryBlockCallbacksIntoManaged())
{
@ -92,11 +77,15 @@ IN_PROCESS_HANDLER::OnAsyncCompletion(
assert(m_pManagedHttpContext != nullptr);
// Call the managed handler for async completion.
return m_pAsyncCompletionHandler(m_pManagedHttpContext, hrCompletionStatus, cbCompletion);
auto status = m_pAsyncCompletionHandler(m_pManagedHttpContext, hrCompletionStatus, cbCompletion);
m_moduleTracer.AsyncCompletionEnd(status);
return status;
}
REQUEST_NOTIFICATION_STATUS IN_PROCESS_HANDLER::ServerShutdownMessage() const
REQUEST_NOTIFICATION_STATUS IN_PROCESS_HANDLER::ServerShutdownMessage()
{
m_moduleTracer.RequestShutdown();
return ShuttingDownHandler::ServerShutdownMessage(m_pW3Context);
}
@ -109,6 +98,8 @@ IN_PROCESS_HANDLER::NotifyDisconnect()
return;
}
m_moduleTracer.RequestDisconnect();
assert(m_pManagedHttpContext != nullptr);
m_pDisconnectHandler(m_pManagedHttpContext);
}
@ -120,6 +111,7 @@ IN_PROCESS_HANDLER::IndicateManagedRequestComplete(
{
m_fManagedRequestComplete = TRUE;
m_pManagedHttpContext = nullptr;
m_moduleTracer.ManagedCompletion();
}
VOID

View File

@ -7,6 +7,7 @@
#include <memory>
#include "iapplication.h"
#include "inprocessapplication.h"
#include "ModuleTracer.h"
class IN_PROCESS_APPLICATION;
@ -71,7 +72,7 @@ public:
private:
REQUEST_NOTIFICATION_STATUS
ServerShutdownMessage() const;
ServerShutdownMessage();
PVOID m_pManagedHttpContext;
BOOL m_fManagedRequestComplete;
@ -83,4 +84,5 @@ private:
PFN_ASYNC_COMPLETION_HANDLER m_pAsyncCompletionHandler;
PFN_DISCONNECT_HANDLER m_pDisconnectHandler;
static ALLOC_CACHE_HANDLER * sm_pAlloc;
ModuleTracer m_moduleTracer;
};

View File

@ -61,6 +61,77 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS
WebConfigHelpers.AddOrModifyAspNetCoreSection("stdoutLogFile", Path.Combine(path, "std")));
}
public static void EnableFreb(this IISDeploymentParameters deploymentParameters, string verbosity, string folderPath)
{
if (!deploymentParameters.PublishApplicationBeforeDeployment)
{
throw new InvalidOperationException("Testing freb requires site to be published.");
}
deploymentParameters.EnableModule("FailedRequestsTracingModule", "%IIS_BIN%\\iisfreb.dll");
// Set the TraceFailedRequestsSection to listend to ANCM events
deploymentParameters.ServerConfigActionList.Add(
(element, _) =>
{
var webServerElement = element
.RequiredElement("system.webServer");
var addElement = webServerElement
.GetOrAdd("tracing")
.GetOrAdd("traceFailedRequests")
.GetOrAdd("add");
addElement.SetAttributeValue("path", "*");
addElement.GetOrAdd("failureDefinitions")
.SetAttributeValue("statusCodes", "200-999");
var traceAreasElement = addElement
.GetOrAdd("traceAreas");
var innerAddElement = traceAreasElement.GetOrAdd("add", "provider", "WWW Server");
innerAddElement.SetAttributeValue("areas", "ANCM");
innerAddElement.SetAttributeValue("verbosity", verbosity);
});
// Set the ANCM traceProviderDefinition to 65536
deploymentParameters.ServerConfigActionList.Add(
(element, _) =>
{
var webServerElement = element
.RequiredElement("system.webServer");
var traceProviderDefinitionsElement = webServerElement
.GetOrAdd("tracing")
.GetOrAdd("traceProviderDefinitions");
var innerAddElement = traceProviderDefinitionsElement.GetOrAdd("add", "name", "WWW Server");
innerAddElement.SetAttributeValue("name", "WWW Server");
innerAddElement.SetAttributeValue("guid", "{3a2a4e84-4c21-4981-ae10-3fda0d9b0f83}");
var areasElement = innerAddElement.GetOrAdd("areas");
var iae = areasElement.GetOrAdd("add", "name", "ANCM");
iae.SetAttributeValue("value", "65536");
});
// Set the freb directory to the published app directory.
deploymentParameters.ServerConfigActionList.Add(
(element, contentRoot) =>
{
var traceFailedRequestsElement = element
.RequiredElement("system.applicationHost")
.Element("sites")
.Element("siteDefaults")
.Element("traceFailedRequestsLogging");
traceFailedRequestsElement.SetAttributeValue("directory", folderPath);
traceFailedRequestsElement.SetAttributeValue("enabled", "true");
traceFailedRequestsElement.SetAttributeValue("maxLogFileSizeKB", "1024");
});
}
public static void TransformPath(this IISDeploymentParameters parameters, Func<string, string, string> transformation)
{
parameters.WebConfigActionList.Add(
@ -89,7 +160,8 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS
}
parameters.ServerConfigActionList.Add(
(element, _) => {
(element, _) =>
{
var webServerElement = element
.RequiredElement("system.webServer");

View File

@ -0,0 +1,118 @@
// 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.Collections.Generic;
using System.IO;
using System.Linq;
using System.Threading.Tasks;
using System.Xml.Linq;
using Microsoft.AspNetCore.Server.IIS.FunctionalTests.Utilities;
using Microsoft.AspNetCore.Server.IntegrationTesting;
using Microsoft.AspNetCore.Server.IntegrationTesting.IIS;
using Microsoft.AspNetCore.Testing.xunit;
using Microsoft.Extensions.Logging;
using Xunit;
namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
{
[Collection(PublishedSitesCollection.Name)]
public class FrebTests : LogFileTestBase
{
private readonly PublishedSitesFixture _fixture;
public FrebTests(PublishedSitesFixture fixture)
{
_fixture = fixture;
}
public static ISet<string[]> FrebChecks()
{
var set = new HashSet<string[]>();
set.Add(new string[] { "ANCM_INPROC_EXECUTE_REQUEST_START" });
set.Add(new string[] { "ANCM_INPROC_EXECUTE_REQUEST_COMPLETION", "1" });
set.Add(new string[] { "ANCM_INPROC_ASYNC_COMPLETION_START" });
set.Add(new string[] { "ANCM_INPROC_ASYNC_COMPLETION_COMPLETION", "0" });
set.Add(new string[] { "ANCM_INPROC_MANAGED_REQUEST_COMPLETION" });
return set;
}
[ConditionalFact]
[RequiresIIS(IISCapability.FailedRequestTracingModule)]
public async Task CheckCommonFrebEvents()
{
var result = await SetupFrebApp();
await result.HttpClient.GetAsync("HelloWorld");
StopServer();
foreach (var data in FrebChecks())
{
AssertFrebLogs(result, data);
}
}
[ConditionalFact]
[RequiresIIS(IISCapability.FailedRequestTracingModule)]
public async Task CheckFailedRequestEvents()
{
var result = await SetupFrebApp();
await result.HttpClient.GetAsync("Throw");
StopServer();
AssertFrebLogs(result, "ANCM_INPROC_ASYNC_COMPLETION_COMPLETION", "2");
}
[ConditionalFact]
[RequiresIIS(IISCapability.FailedRequestTracingModule)]
public async Task CheckFrebDisconnect()
{
var result = await SetupFrebApp();
using (var connection = new TestConnection(result.HttpClient.BaseAddress.Port))
{
await connection.Send(
"GET /WaitForAbort HTTP/1.1",
"Host: localhost",
"Connection: close",
"",
"");
await result.HttpClient.RetryRequestAsync("/WaitingRequestCount", async message => await message.Content.ReadAsStringAsync() == "1");
}
StopServer();
AssertFrebLogs(result, "ANCM_INPROC_REQUEST_DISCONNECT");
}
private async Task<IISDeploymentResult> SetupFrebApp()
{
var parameters = _fixture.GetBaseDeploymentParameters(publish: true);
parameters.EnableFreb("Verbose", _logFolderPath);
Directory.CreateDirectory(_logFolderPath);
var result = await DeployAsync(parameters);
return result;
}
private void AssertFrebLogs(IISDeploymentResult result, params string[] data)
{
var folderPath = Helpers.GetFrebFolder(_logFolderPath, result);
var fileString = Directory.GetFiles(folderPath).Where(f => f.EndsWith("xml")).OrderBy(x => x).Last();
var xDocument = XDocument.Load(fileString).Root;
var nameSpace = (XNamespace)"http://schemas.microsoft.com/win/2004/08/events/event";
var elements = xDocument.Descendants(nameSpace + "Event");
var element = elements.Where(el => el.Descendants(nameSpace + "RenderingInfo").Single().Descendants(nameSpace + "Opcode").Single().Value == data[0]);
Assert.Single(element);
if (data.Length > 1)
{
var requestStatus = element.Single().Element(nameSpace + "EventData").Descendants().Where(el => el.Attribute("Name").Value == "requestStatus").Single();
Assert.Equal(data[1], requestStatus.Value);
}
}
}
}

View File

@ -63,6 +63,18 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
await Task.WhenAll(tasks);
}
public static string GetFrebFolder(string folder, IISDeploymentResult result)
{
if (result.DeploymentParameters.ServerType == ServerType.IISExpress)
{
return Path.Combine(folder, result.DeploymentParameters.SiteName);
}
else
{
return Path.Combine(folder, "W3SVC1");
}
}
public static void CopyFiles(DirectoryInfo source, DirectoryInfo target, ILogger logger)
{
foreach (DirectoryInfo directoryInfo in source.GetDirectories())
@ -113,6 +125,27 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
return response;
}
public static async Task Retry(Func<Task> func, int attempts, int msDelay)
{
var exceptions = new List<Exception>();
for (var attempt = 0; attempt < attempts; attempt++)
{
try
{
await func();
return;
}
catch (Exception e)
{
exceptions.Add(e);
}
await Task.Delay(msDelay);
}
throw new AggregateException(exceptions);
}
public static void AssertWorkerProcessStop(this IISDeploymentResult deploymentResult, int? timeout = null)
{
var hostProcess = deploymentResult.HostProcess;

View File

@ -15,6 +15,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
ShutdownToken = 8,
DynamicCompression = 16,
ApplicationInitialization = 32,
TracingModule = 64
TracingModule = 64,
FailedRequestTracingModule = 128
}
}

View File

@ -24,6 +24,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
private static readonly bool _dynamicCompressionAvailable;
private static readonly bool _applicationInitializationModule;
private static readonly bool _tracingModuleAvailable;
private static readonly bool _frebTracingModuleAvailable;
static RequiresIISAttribute()
{
@ -90,6 +91,9 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
_tracingModuleAvailable = File.Exists(Path.Combine(Environment.SystemDirectory, "inetsrv", "iisetw.dll"));
_frebTracingModuleAvailable = File.Exists(Path.Combine(Environment.SystemDirectory, "inetsrv", "iisfreb.dll"));
var iisRegistryKey = Registry.LocalMachine.OpenSubKey(@"Software\Microsoft\InetStp", writable: false);
if (iisRegistryKey == null)
{
@ -161,12 +165,22 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
}
}
if (capabilities.HasFlag(IISCapability.TracingModule))
{
IsMet &= _tracingModuleAvailable;
if (!_tracingModuleAvailable)
{
SkipReason += "The machine does not have IIS TracingModule installed.";
SkipReason += "The machine does not have IIS Failed Request Tracing Module installed.";
}
}
if (capabilities.HasFlag(IISCapability.FailedRequestTracingModule))
{
IsMet &= _frebTracingModuleAvailable;
if (!_frebTracingModuleAvailable)
{
SkipReason += "The machine does not have IIS Failed Request Tracing Module installed.";
}
}
}

View File

@ -38,7 +38,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
// ANCM v2 does retry on port collisions, so no retries should be required.
var attempts = (ancmVersion == AncmVersion.AspNetCoreModule) ? 2 : 1;
return Retry(async () =>
return Helpers.Retry(async () =>
{
const int numApps = 10;
@ -75,27 +75,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
}
}
},
attempts: attempts);
}
private async Task Retry(Func<Task> func, int attempts)
{
var exceptions = new List<Exception>();
for (var attempt = 0; attempt < attempts; attempt++)
{
try
{
await func();
return;
}
catch (Exception e)
{
exceptions.Add(e);
}
}
throw new AggregateException(exceptions);
attempts: attempts, msDelay: 0);
}
}
}