Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix start-time of WebApi request-tracking #334

Merged
merged 5 commits into from
Jun 23, 2022
Merged

Fix start-time of WebApi request-tracking #334

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
b8fbd04
Correctly track request starttime
fgheysels Jun 8, 2022
fff793a
remove unnecessary whitespace
fgheysels Jun 8, 2022
ba7aa09
Update src/Arcus.WebApi.Logging/Arcus.WebApi.Logging.csproj
fgheysels Jun 23, 2022
21299e4
Update Arcus.Observability dependencies for .NET Core target
fgheysels Jun 23, 2022
5d38585
simplify dependecies
fgheysels Jun 23, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 7 additions & 6 deletions src/Arcus.WebApi.Logging.Core/Arcus.WebApi.Logging.Core.csproj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,16 +32,17 @@
<PackageReference Include="Microsoft.Extensions.Logging" Version="2.2.0" />
</ItemGroup>

<ItemGroup Condition="'$(TargetFramework)' == 'net6.0'">
<PackageReference Include="Arcus.Observability.Telemetry.Core" Version="[2.4.0,3.0.0)" />
<PackageReference Include="Arcus.Observability.Correlation" Version="[2.4.0,3.0.0)" />
<ItemGroup Condition="'$(TargetFramework)' == 'net6.0'">
<PackageReference Include="Guard.Net" Version="2.0.0" />
</ItemGroup>

<ItemGroup Condition="'$(TargetFramework)' != 'net6.0'">
<PackageReference Include="Arcus.Observability.Telemetry.Core" Version="[2.2.1,3.0.0)" />
<PackageReference Include="Arcus.Observability.Correlation" Version="[2.2.1,3.0.0)" />
<ItemGroup Condition="'$(TargetFramework)' != 'net6.0'">
<PackageReference Include="Guard.Net" Version="1.2.0" />
</ItemGroup>

<ItemGroup>
<PackageReference Include="Arcus.Observability.Telemetry.Core" Version="[2.5.0,3.0.0)" />
<PackageReference Include="Arcus.Observability.Correlation" Version="[2.5.0,3.0.0)" />
</ItemGroup>

</Project>
19 changes: 9 additions & 10 deletions src/Arcus.WebApi.Logging/Arcus.WebApi.Logging.csproj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,21 +36,20 @@
</ItemGroup>

<ItemGroup Condition="'$(TargetFramework)' == 'net6.0'">
<PackageReference Include="Guard.Net" Version="2.0.0" />
<PackageReference Include="Arcus.Observability.Telemetry.Core" Version="[2.4.0,3.0.0)" />
<PackageReference Include="Arcus.Observability.Telemetry.AspNetCore" Version="[2.4.0,3.0.0)" />
<PackageReference Include="Arcus.Observability.Correlation" Version="[2.4.0,3.0.0)" />
<PackageReference Include="Arcus.Observability.Telemetry.Serilog.Enrichers" Version="[2.4.0,3.0.0)" />
<PackageReference Include="Guard.Net" Version="2.0.0" />
</ItemGroup>

<ItemGroup Condition="'$(TargetFramework)' != 'net6.0'">
<PackageReference Include="Guard.Net" Version="1.2.0" />
<PackageReference Include="Arcus.Observability.Telemetry.Core" Version="[2.2.1,3.0.0)" />
<PackageReference Include="Arcus.Observability.Telemetry.AspNetCore" Version="[2.2.1,3.0.0)" />
<PackageReference Include="Arcus.Observability.Correlation" Version="[2.2.1,3.0.0)" />
<PackageReference Include="Arcus.Observability.Telemetry.Serilog.Enrichers" Version="[2.2.1,3.0.0)" />
<PackageReference Include="Guard.Net" Version="1.2.0" />
</ItemGroup>

<ItemGroup>
<PackageReference Include="Arcus.Observability.Telemetry.Core" Version="[2.5.0,3.0.0)" />
<PackageReference Include="Arcus.Observability.Telemetry.AspNetCore" Version="[2.5.0,3.0.0)" />
<PackageReference Include="Arcus.Observability.Correlation" Version="[2.5.0,3.0.0)" />
<PackageReference Include="Arcus.Observability.Telemetry.Serilog.Enrichers" Version="[2.5.0,3.0.0)" />
</ItemGroup>

<ItemGroup>
<ProjectReference Include="..\Arcus.WebApi.Logging.Core\Arcus.WebApi.Logging.Core.csproj" />
</ItemGroup>
Expand Down
114 changes: 58 additions & 56 deletions src/Arcus.WebApi.Logging/RequestTrackingMiddleware.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
using System.Linq;
using System.Net;
using System.Threading.Tasks;
using Arcus.Observability.Telemetry.Core;
using GuardNet;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Http.Extensions;
Expand Down Expand Up @@ -48,7 +49,7 @@ public RequestTrackingMiddleware(
/// Gets the consumer-configured options to control the behavior of the request tracking.
/// </summary>
public RequestTrackingOptions Options { get; }

/// <summary>
/// Request handling method.
/// </summary>
Expand Down Expand Up @@ -83,7 +84,7 @@ public async Task Invoke(HttpContext httpContext)
RequestTrackingAttribute[] attributes = DetermineAppliedAttributes(endpoint);
Exclude filter = DetermineExclusionFilter(attributes);
StatusCodeRange[] trackedStatusCodeRanges = DetermineTrackedStatusCodeRanges(attributes);

await TrackRequest(httpContext, filter, trackedStatusCodeRanges);
}
}
Expand All @@ -92,7 +93,7 @@ public async Task Invoke(HttpContext httpContext)
private bool IsRequestPathOmitted(HttpRequest request)
{
IEnumerable<string> allOmittedRoutes = Options.OmittedRoutes ?? new Collection<string>();
string[] matchedOmittedRoutes =
string[] matchedOmittedRoutes =
allOmittedRoutes
.Select(omittedRoute => omittedRoute?.StartsWith("/") == true ? omittedRoute : "/" + omittedRoute)
.Where(omittedRoute => request.Path.StartsWithSegments(omittedRoute, StringComparison.OrdinalIgnoreCase))
Expand All @@ -103,10 +104,10 @@ private bool IsRequestPathOmitted(HttpRequest request)
string endpoint = request.GetDisplayUrl();
string formattedOmittedRoutes = String.Join(", ", matchedOmittedRoutes);
_logger.LogTrace("Skip request tracking for endpoint '{Endpoint}' due to an omitted route(s) '{OmittedRoutes}' specified in the options", endpoint, formattedOmittedRoutes);

return true;
}

return false;
}

Expand All @@ -117,7 +118,7 @@ private RequestTrackingAttribute[] DetermineAppliedAttributes(IEndpointFeature e
_logger.LogTrace("Cannot determine whether or not the endpoint contains the '{OptionsAttribute}' because the endpoint tracking (`IApplicationBuilder.UseRouting()` or `.UseEndpointRouting()`) was not activated before the request tracking middleware; or the route was not found", nameof(RequestTrackingAttribute));
return Array.Empty<RequestTrackingAttribute>();
}

RequestTrackingAttribute[] attributes = endpoint.Endpoint.Metadata.OfType<RequestTrackingAttribute>().ToArray();
return attributes;
}
Expand All @@ -129,7 +130,7 @@ private Exclude DetermineExclusionFilter(RequestTrackingAttribute[] attributes)
_logger.LogTrace("No '{Attribute}' found on endpoint, continue with request tracking including both request and response bodies", nameof(ExcludeRequestTrackingAttribute));
return Exclude.None;
}

Exclude filter = attributes.Aggregate(Exclude.None, (acc, item) => acc | item.Filter);
return filter;
}
Expand All @@ -141,54 +142,55 @@ private StatusCodeRange[] DetermineTrackedStatusCodeRanges(RequestTrackingAttrib
_logger.LogTrace("No '{Attribute}' found on endpoint, continue with request tracking including all HTTP status codes", nameof(ExcludeRequestTrackingAttribute));
return Array.Empty<StatusCodeRange>();
}
StatusCodeRange[] statusCodes =

StatusCodeRange[] statusCodes =
attributes.Where(attribute => attribute.StatusCodeRange != null)
.Select(attribute => attribute.StatusCodeRange)
.ToArray();

return statusCodes;
}

private async Task TrackRequest(HttpContext httpContext, Exclude attributeExcludeFilter, StatusCodeRange[] attributeTrackedStatusCodes)
{
var stopwatch = Stopwatch.StartNew();
bool includeRequestBody = ShouldIncludeRequestBody(attributeExcludeFilter);
bool includeResponseBody = ShouldIncludeResponseBody(attributeExcludeFilter);

string requestBody = await GetPotentialRequestBodyAsync(httpContext, includeRequestBody);

// Response body doesn't support (built-in) buffering and is not seekable, so we're storing temporary the response stream in our own seekable stream,
// which we later (*) replace back with the original response stream.
// If we don't store it in our own seekable stream first, we would read the response stream for tracking and could not use the same stream to respond to the request.
Stream originalResponseBodyStream = null;
using (Stream temporaryResponseBodyStream = DetermineResponseBodyBuffer(includeResponseBody))
using (DurationMeasurement duration = DurationMeasurement.Start())
{
if (includeResponseBody)
{
originalResponseBodyStream = httpContext.Response.Body;
httpContext.Response.Body = temporaryResponseBodyStream;
}
bool includeRequestBody = ShouldIncludeRequestBody(attributeExcludeFilter);
bool includeResponseBody = ShouldIncludeResponseBody(attributeExcludeFilter);

try
{
await _next(httpContext);
}
finally
string requestBody = await GetPotentialRequestBodyAsync(httpContext, includeRequestBody);

// Response body doesn't support (built-in) buffering and is not seekable, so we're storing temporary the response stream in our own seekable stream,
// which we later (*) replace back with the original response stream.
// If we don't store it in our own seekable stream first, we would read the response stream for tracking and could not use the same stream to respond to the request.
Stream originalResponseBodyStream = null;
using (Stream temporaryResponseBodyStream = DetermineResponseBodyBuffer(includeResponseBody))
{
if (AllowedToTrackStatusCode(httpContext, attributeTrackedStatusCodes))
if (includeResponseBody)
{
string responseBody = await GetPotentialResponseBodyAsync(httpContext, includeResponseBody);

stopwatch.Stop();
LogRequest(requestBody, responseBody, httpContext, stopwatch.Elapsed);
originalResponseBodyStream = httpContext.Response.Body;
httpContext.Response.Body = temporaryResponseBodyStream;
}

if (includeResponseBody)
try
{
// (*) Copy back the seekable/temporary response body stream to the original response body stream,
// for the remaining middleware components that comes after this one.
await CopyTemporaryStreamToResponseStreamAsync(temporaryResponseBodyStream, originalResponseBodyStream);
await _next(httpContext);
}
finally
{
if (AllowedToTrackStatusCode(httpContext, attributeTrackedStatusCodes))
{
string responseBody = await GetPotentialResponseBodyAsync(httpContext, includeResponseBody);

LogRequest(requestBody, responseBody, httpContext, duration);
}

if (includeResponseBody)
{
// (*) Copy back the seekable/temporary response body stream to the original response body stream,
// for the remaining middleware components that comes after this one.
await CopyTemporaryStreamToResponseStreamAsync(temporaryResponseBodyStream, originalResponseBodyStream);
}
}
}
}
Expand All @@ -199,9 +201,9 @@ private bool ShouldIncludeRequestBody(Exclude attributeExcludeFilter)
bool includeRequestBody = Options.IncludeRequestBody && attributeExcludeFilter.HasFlag(Exclude.RequestBody) == false;
if (includeRequestBody)
{
_logger.LogTrace("Request tracking will include the request's body as the options '{OptionName}' = '{OptionValue}' and the '{Attribute}' doesn't exclude the request body", nameof(Options.IncludeRequestBody), Options.IncludeRequestBody, nameof(RequestTrackingAttribute));
_logger.LogTrace("Request tracking will include the request's body as the options '{OptionName}' = '{OptionValue}' and the '{Attribute}' doesn't exclude the request body", nameof(Options.IncludeRequestBody), Options.IncludeRequestBody, nameof(RequestTrackingAttribute));
}

return includeRequestBody;
}

Expand All @@ -210,7 +212,7 @@ private bool ShouldIncludeResponseBody(Exclude attributeExcludeFilter)
bool includeResponseBody = Options.IncludeResponseBody && attributeExcludeFilter.HasFlag(Exclude.ResponseBody) == false;
if (includeResponseBody)
{
_logger.LogTrace("Request tracking will include the response's body as the options '{OptionName}' = '{OptionValue}' and the '{Attribute}' doesn't exclude the response body", nameof(Options.IncludeResponseBody), Options.IncludeResponseBody, nameof(RequestTrackingAttribute));
_logger.LogTrace("Request tracking will include the response's body as the options '{OptionName}' = '{OptionValue}' and the '{Attribute}' doesn't exclude the response body", nameof(Options.IncludeResponseBody), Options.IncludeResponseBody, nameof(RequestTrackingAttribute));
}

return includeResponseBody;
Expand All @@ -227,7 +229,7 @@ private static Stream DetermineResponseBodyBuffer(bool includeResponseBody)
return Stream.Null;
}

private void LogRequest(string requestBody, string responseBody, HttpContext httpContext, TimeSpan duration)
private void LogRequest(string requestBody, string responseBody, HttpContext httpContext, DurationMeasurement duration)
{
try
{
Expand Down Expand Up @@ -289,10 +291,10 @@ private async Task<string> GetPotentialRequestBodyAsync(HttpContext httpContext,
if (includeRequestBody)
{
httpContext.Request.EnableBuffering();

string requestBody = await GetBodyAsync(httpContext.Request.Body, Options.RequestBodyBufferSize, "Request");
string sanitizedBody = SanitizeRequestBody(httpContext.Request, requestBody);

return sanitizedBody;
}

Expand All @@ -316,10 +318,10 @@ private async Task<string> GetPotentialResponseBodyAsync(HttpContext httpContext
{
string responseBody = await GetBodyAsync(httpContext.Response.Body, Options.ResponseBodyBufferSize, "Response");
string sanitizedBody = SanitizeResponseBody(httpContext.Response, responseBody);

return sanitizedBody;
}

return null;
}

Expand All @@ -343,7 +345,7 @@ private async Task<string> GetBodyAsync(Stream body, int? maxLength, string targ
_logger.LogTrace("Found {Target} body to be tracked", target);
return sanitizedBody;
}

_logger.LogWarning("No {Target} body was found to be tracked", target);
return null;
}
Expand Down Expand Up @@ -376,7 +378,7 @@ private static async Task<string> SanitizeStreamAsync(Stream stream, int? maxLen
{
var buffer = new char[maxLength.Value];
await reader.ReadBlockAsync(buffer, 0, buffer.Length);
contents = new String(buffer);
contents = new String(buffer);
}
else
{
Expand Down Expand Up @@ -408,21 +410,21 @@ private static async Task<string> SanitizeStreamAsync(Stream stream, int? maxLen

private bool AllowedToTrackStatusCode(HttpContext httpContext, IEnumerable<StatusCodeRange> attributeTrackedStatusCodes)
{
IEnumerable<HttpStatusCode> optionsTrackedStatusCodes =
IEnumerable<HttpStatusCode> optionsTrackedStatusCodes =
Options.TrackedStatusCodes ?? Enumerable.Empty<HttpStatusCode>();

IEnumerable<StatusCodeRange> optionsTrackedStatusCodeRanges =
Options.TrackedStatusCodeRanges ?? Enumerable.Empty<StatusCodeRange>();
StatusCodeRange[] combinedStatusCodeRanges =

StatusCodeRange[] combinedStatusCodeRanges =
optionsTrackedStatusCodes
.Select(code => new StatusCodeRange((int) code))
.Select(code => new StatusCodeRange((int)code))
.Concat(optionsTrackedStatusCodeRanges)
.Concat(attributeTrackedStatusCodes)
.Where(range => range != null)
.Distinct().ToArray();

bool allowedToTrackStatusCode =
bool allowedToTrackStatusCode =
combinedStatusCodeRanges.Length <= 0
|| combinedStatusCodeRanges.Any(range => range.IsWithinRange(httpContext.Response.StatusCode));

Expand All @@ -435,7 +437,7 @@ private bool AllowedToTrackStatusCode(HttpContext httpContext, IEnumerable<Statu
{
_logger.LogTrace("Request tracking for this endpoint is disallowed as the response status code '{ResponseStatusCode}' is not within the allowed tracked status code ranges '{TrackedStatusCodes}'", httpContext.Response.StatusCode, formattedStatusCodes);
}

return allowedToTrackStatusCode;
}

Expand Down