Skip to content

Commit

Permalink
feat: track http request data in http trigger (#448)
Browse files Browse the repository at this point in the history
* feat: track http request data in http trigger

* pr-fix: better defect detection

* pr-fix: timeout

* Update docs/preview/03-Features/writing-different-telemetry-types.md

Co-authored-by: Frederik Gheysels <frederik.gheysels@telenet.be>

* pr-fix: more stable metric telemetry unit tests

Co-authored-by: Frederik Gheysels <frederik.gheysels@telenet.be>
  • Loading branch information
stijnmoreels and fgheysels committed Aug 26, 2022
1 parent 68bd459 commit e192925
Show file tree
Hide file tree
Showing 11 changed files with 721 additions and 17 deletions.
46 changes: 45 additions & 1 deletion docs/preview/03-Features/writing-different-telemetry-types.md
Original file line number Diff line number Diff line change
Expand Up @@ -555,7 +555,7 @@ using (var measurement = DurationMeasurement.Start())

We provide overloads to configure the Azure EventHubs consumer group (default: `$Default`) and a functional operation name (default: `Process`).

### Incoming HTTP requests
### Incoming HTTP requests in API's
Requests allow you to keep track of the HTTP requests that are performed against your API and what the response was that was sent out.

**Installation**
Expand Down Expand Up @@ -593,6 +593,50 @@ using (var measurement = DurationMeasurement.Start())

> 💡 Note that [Arcus Web API request tracking middleware](https://webapi.arcus-azure.net/features/logging#logging-incoming-requests) can already do this for you in a ASP.NET Core application
### Incoming HTTP requests in Azure Function HTTP trigger
Requests allow you to keep track of the HTTP requests that are performed against your Azure Function HTTP trigger and what the response was that was sent out.

**Installation**

For isolated Azure Functions, you'll have to install an additional package if you want to track the `HttpRequestData`:

```shell
PM > Install-Package Arcus.Observability.Telemetry.AzureFunctions
```

**Example**

Here is how you can keep track of requests:

```csharp
using Sytem.Net;
using Microsoft.Extensions.Logging;

public async Task<HttpResponseData> Run(
[HttpTrigger(AuthorizationLevel.Function, "post", Route = "v1/order")] HttpRequestData request,
FunctionContext executionContext)
{
var statusCode = default(HttpStatusCode);

// Start tracking request.
using (var measurement = DurationMeasurement.Start())
{
try
{
// Processing...
statusCode = HttpStatusCode.Ok;
return request.CreateResponse(statusCode)
}
finally
{
logger.LogRequest(request, statusCode, measurement);
// Output: {"RequestMethod": "POST", "RequestHost": "http://localhost:5000/", "RequestUri": "http://localhost:5000/v1/order", "ResponseStatusCode": 200, "RequestDuration": "00:00:00.0191554", "RequestTime": "03/23/2020 10:12:55 +00:00", "Context": {}}
}
}
}
```

### Incoming custom requests
Requests allow you to keep track of incoming messages. We provide an extension to track type of requests that aren't out-of-the-box so you can track your custom systems.

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -26,11 +26,16 @@
<ItemGroup Condition="'$(TargetFramework)' == 'net6.0'">
<PackageReference Include="Guard.Net" Version="2.0.0" />
<PackageReference Include="Microsoft.Extensions.Logging" Version="6.0.0" />
<PackageReference Include="Microsoft.Azure.Functions.Worker.Core" Version="1.6.0" />
</ItemGroup>

<ItemGroup Condition="'$(TargetFramework)' != 'net6.0'">
<PackageReference Include="Guard.Net" Version="1.2.0" />
<PackageReference Include="Microsoft.Extensions.Logging" Version="3.1.8" />
</ItemGroup>

<ItemGroup>
<ProjectReference Include="..\Arcus.Observability.Telemetry.Core\Arcus.Observability.Telemetry.Core.csproj" />
</ItemGroup>

</Project>
Original file line number Diff line number Diff line change
@@ -0,0 +1,139 @@
using System;
using System.Collections.Generic;
using System.Net;
using Arcus.Observability.Telemetry.Core;
using Arcus.Observability.Telemetry.Core.Logging;
using GuardNet;
#if NET6_0
using Microsoft.Azure.Functions.Worker.Http;
#endif

// ReSharper disable once CheckNamespace
namespace Microsoft.Extensions.Logging
{
#if NET6_0
/// <summary>
/// Telemetry extensions on the <see cref="ILogger"/> instance to write Application Insights compatible log messages.
/// </summary>
// ReSharper disable once InconsistentNaming
public static class ILoggerRequestExtensions
{
/// <summary>
/// Logs an HTTP request.
/// </summary>
/// <param name="logger">The logger to track the telemetry.</param>
/// <param name="request">The incoming HTTP request that was processed.</param>
/// <param name="responseStatusCode">The HTTP status code returned by the service.</param>
/// <param name="measurement">The instance to measure the duration of the HTTP request.</param>
/// <param name="context">The context that provides more insights on the tracked HTTP request.</param>
/// <exception cref="ArgumentNullException">
/// Thrown when the <paramref name="logger"/>, <paramref name="request"/>, or the <paramref name="measurement"/> is <c>null</c>.
/// </exception>
public static void LogRequest(
this ILogger logger,
HttpRequestData request,
HttpStatusCode responseStatusCode,
DurationMeasurement measurement,
Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry");
Guard.NotNull(request, nameof(request), "Requires a HTTP request instance to track a HTTP request");
Guard.NotNull(measurement, nameof(measurement), "Requires an measurement instance to time the duration of the HTTP request");

LogRequest(logger, request, responseStatusCode, measurement.StartTime, measurement.Elapsed, context);
}

/// <summary>
/// Logs an HTTP request.
/// </summary>
/// <param name="logger">The logger to track the telemetry.</param>
/// <param name="request">The incoming HTTP request that was processed.</param>
/// <param name="responseStatusCode">The HTTP status code returned by the service.</param>
/// <param name="startTime">The time when the HTTP request was received.</param>
/// <param name="duration">The duration of the HTTP request processing operation.</param>
/// <param name="context">The context that provides more insights on the tracked HTTP request.</param>
/// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> or the <paramref name="request"/> is <c>null</c>.</exception>
/// <exception cref="ArgumentOutOfRangeException">Thrown when the <paramref name="duration"/> is a negative time range.</exception>
public static void LogRequest(
this ILogger logger,
HttpRequestData request,
HttpStatusCode responseStatusCode,
DateTimeOffset startTime,
TimeSpan duration,
Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry");
Guard.NotNull(request, nameof(request), "Requires a HTTP request instance to track a HTTP request");
Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request operation");

LogRequest(logger, request, responseStatusCode, operationName: null, startTime, duration, context);
}

/// <summary>
/// Logs an HTTP request.
/// </summary>
/// <param name="logger">The logger to track the telemetry.</param>
/// <param name="request">The incoming HTTP request that was processed.</param>
/// <param name="responseStatusCode">The HTTP status code returned by the service.</param>
/// <param name="operationName">The name of the operation of the request.</param>
/// <param name="measurement">The instance to measure the duration of the HTTP request.</param>
/// <param name="context">The context that provides more insights on the tracked HTTP request.</param>
/// <exception cref="ArgumentNullException">
/// Thrown when the <paramref name="logger"/>, <paramref name="request"/>, or the <paramref name="measurement"/> is <c>null</c>.
/// </exception>
public static void LogRequest(
this ILogger logger,
HttpRequestData request,
HttpStatusCode responseStatusCode,
string operationName,
DurationMeasurement measurement,
Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry");
Guard.NotNull(request, nameof(request), "Requires a HTTP request instance to track a HTTP request");
Guard.NotNull(measurement, nameof(measurement), "Requires an measurement instance to time the duration of the HTTP request");

LogRequest(logger, request, responseStatusCode, operationName, measurement.StartTime, measurement.Elapsed, context);
}

/// <summary>
/// Logs an HTTP request.
/// </summary>
/// <param name="logger">The logger to track the telemetry.</param>
/// <param name="request">The incoming HTTP request that was processed.</param>
/// <param name="responseStatusCode">The HTTP status code returned by the service.</param>
/// <param name="operationName">The name of the operation of the request.</param>
/// <param name="startTime">The time when the HTTP request was received.</param>
/// <param name="duration">The duration of the HTTP request processing operation.</param>
/// <param name="context">The context that provides more insights on the tracked HTTP request.</param>
/// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> or the <paramref name="request"/> is <c>null</c>.</exception>
/// <exception cref="ArgumentOutOfRangeException">Thrown when the <paramref name="duration"/> is a negative time range.</exception>
public static void LogRequest(
this ILogger logger,
HttpRequestData request,
HttpStatusCode responseStatusCode,
string operationName,
DateTimeOffset startTime,
TimeSpan duration,
Dictionary<string, object> context = null)
{
Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry");
Guard.NotNull(request, nameof(request), "Requires a HTTP request instance to track a HTTP request");
Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request operation");

context = context ?? new Dictionary<string, object>();

logger.LogWarning(MessageFormats.RequestFormat,
RequestLogEntry.CreateForHttpRequest(request.Method,
request.Url.Scheme,
request.Url.Host,
request.Url.AbsolutePath,
operationName,
(int) responseStatusCode,
startTime,
duration,
context));
}
}
#endif
}
Original file line number Diff line number Diff line change
Expand Up @@ -327,10 +327,7 @@ public static partial class ILoggerExtensions
/// the <paramref name="request"/>'s scheme contains whitespace,
/// the <paramref name="request"/>'s host contains whitespace,
/// </exception>
/// <exception cref="ArgumentOutOfRangeException">
/// Thrown when the <paramref name="responseStatusCode"/>'s status code is outside the 0-999 inclusively,
/// the <paramref name="duration"/> is a negative time range.
/// </exception>
/// <exception cref="ArgumentOutOfRangeException">Thrown when the <paramref name="duration"/> is a negative time range.</exception>
public static void LogRequest(
this ILogger logger,
HttpRequestMessage request,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@

<ItemGroup>
<ProjectReference Include="..\Arcus.Observability.Telemetry.AspNetCore\Arcus.Observability.Telemetry.AspNetCore.csproj" />
<ProjectReference Include="..\Arcus.Observability.Telemetry.AzureFunctions\Arcus.Observability.Telemetry.AzureFunctions.csproj" />
<ProjectReference Include="..\Arcus.Observability.Telemetry.Core\Arcus.Observability.Telemetry.Core.csproj" />
<ProjectReference Include="..\Arcus.Observability.Telemetry.Sql\Arcus.Observability.Telemetry.Sql.csproj" />
<ProjectReference Include="..\Arcus.Observability.Telemetry.Serilog.Filters\Arcus.Observability.Telemetry.Serilog.Filters.csproj" />
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -138,7 +138,7 @@ protected async Task RetryAssertUntilTelemetryShouldBeAvailableAsync(Func<Applic
{
var client = new ApplicationInsightsClient(dataClient, ApplicationId);
await assertion(client);
}, timeout: TimeSpan.FromMinutes(7));
}, timeout: TimeSpan.FromMinutes(8));
}
}

Expand All @@ -152,20 +152,38 @@ private ApplicationInsightsDataClient CreateApplicationInsightsClient()

private static async Task RetryAssertUntilTelemetryShouldBeAvailableAsync(Func<Task> assertion, TimeSpan timeout)
{
Exception lastException = null;
PolicyResult result =
await Policy.TimeoutAsync(timeout)
.WrapAsync(Policy.Handle<Exception>()
.WaitAndRetryForeverAsync(index => TimeSpan.FromSeconds(1)))
.ExecuteAndCaptureAsync(assertion);
.ExecuteAndCaptureAsync(async () =>
{
try
{
await assertion();
}
catch (Exception exception)
{
lastException = exception;
throw;
}
});

if (result.Outcome is OutcomeType.Failure)
{
if (result.FinalException is TimeoutRejectedException
&& result.FinalException.InnerException != null)
&& result.FinalException.InnerException != null
&& result.FinalException.InnerException is not TaskCanceledException)
{
throw result.FinalException.InnerException;
}

if (lastException != null)
{
throw lastException;
}

throw result.FinalException;
}
}
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,87 @@
using System;
using System.Collections.Generic;
using System.Net;
using System.Net.Http;
using System.Threading.Tasks;
using Arcus.Observability.Correlation;
using Microsoft.Azure.ApplicationInsights.Query.Models;
using Microsoft.Azure.Functions.Worker;
using Microsoft.Azure.Functions.Worker.Http;
using Microsoft.Extensions.Logging;
using Moq;
using Serilog;
using Xunit;
using Xunit.Abstractions;

namespace Arcus.Observability.Tests.Integration.Serilog.Sinks.ApplicationInsights
{
public class HttpRequestDataTests : ApplicationInsightsSinkTests
{
public HttpRequestDataTests(ITestOutputHelper outputWriter) : base(outputWriter)
{
}

[Fact]
public async Task LogRequest_SinksToApplicationInsightsWithCorrelation_ResultsInRequestTelemetry()
{
// Arrange
var correlation = new CorrelationInfo($"operation-{Guid.NewGuid()}", $"transaction-{Guid.NewGuid()}", $"parent-{Guid.NewGuid()}");
var accessor = new DefaultCorrelationInfoAccessor();
accessor.SetCorrelationInfo(correlation);
LoggerConfiguration.Enrich.WithCorrelationInfo(accessor);

var operationName = "sampleoperation";
HttpMethod httpMethod = GenerateHttpMethod();
var requestUri = new Uri(BogusGenerator.Internet.UrlWithPath());
HttpRequestData request = CreateStubRequest(httpMethod, requestUri);
var statusCode = BogusGenerator.PickRandom<HttpStatusCode>();

TimeSpan duration = BogusGenerator.Date.Timespan();
DateTimeOffset startTime = DateTimeOffset.Now;
Dictionary<string, object> telemetryContext = CreateTestTelemetryContext();

// Act
Logger.LogRequest(request, statusCode, operationName, startTime, duration, telemetryContext);

// Assert
await RetryAssertUntilTelemetryShouldBeAvailableAsync(async client =>
{
EventsRequestResult[] results = await client.GetRequestsAsync();
AssertX.Any(results, result =>
{
Assert.Equal($"{requestUri.Scheme}://{requestUri.Host}{requestUri.AbsolutePath}", result.Request.Url);
Assert.Equal(((int) statusCode).ToString(), result.Request.ResultCode);
Assert.Equal($"{httpMethod.Method} {operationName}", result.Operation.Name);
Assert.Equal(correlation.OperationId, result.Request.Id);
Assert.Equal(correlation.TransactionId, result.Operation.Id);
Assert.Equal(correlation.OperationParentId, result.Operation.ParentId);
});
});
}

private HttpMethod GenerateHttpMethod()
{
return BogusGenerator.PickRandom(
HttpMethod.Get,
HttpMethod.Delete,
HttpMethod.Head,
HttpMethod.Options,
HttpMethod.Patch,
HttpMethod.Post,
HttpMethod.Put,
HttpMethod.Trace);
}

private static HttpRequestData CreateStubRequest(HttpMethod method, Uri requestUri)
{
var context = Mock.Of<FunctionContext>();

var stub = new Mock<HttpRequestData>(context);
stub.Setup(s => s.Method).Returns(method.Method);
stub.Setup(s => s.Url).Returns(requestUri);

return stub.Object;
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,7 @@ public RequestTests(ITestOutputHelper outputWriter) : base(outputWriter)
{
}

[Fact]
[Fact]
public async Task LogRequest_SinksToApplicationInsightsWithCorrelation_ResultsInRequestTelemetry()
{
// Arrange
Expand Down
Loading

0 comments on commit e192925

Please sign in to comment.