Request Middleware is not logging the correct timestamp

[fgheysels]

The request-middleware which logs incoming requests to log-sinks, is not using the correct DateTime for logging the timestamp of an incoming request.

When we dig into the RequestTrackingMiddleware class, we can find the TrackRequest method which contains this code:

As can be seen, the next middleware component is executed, and only if that has been done, the request is being logged.

When running the service-to-service-observability-poc, this problem becomes visible, see also this issue and the below screenshot:

the POST market operation happens first and initiates all the other traces that are logged, yet, the POST market operation appears at the bottom of the timeline and it looks like all other requests were happening before the POST market operation happened. However, all those other requests were triggered because of the POST market operation.

Digging a little bit further, this can be found in the RequestLogEntry class of the Arcus.Observability repository:

 public RequestLogEntry(
            string method, 
            string host, 
            string uri, 
            string operationName,
            int statusCode,
            TimeSpan duration,
            IDictionary<string, object> context)
            : this(method, host, uri, operationName, statusCode, sourceSystem: RequestSourceSystem.Http, duration, requestTime: DateTimeOffset.UtcNow.ToString(FormatSpecifiers.InvariantTimestampFormat), context)

As can be seen, the requestTime is always set to DateTimeOffset.UtcNow , however, this is not the correct date at which the request was received, since the LogRequest is only done after the complete ASP.NET pipeline was executed.

Ideally, we would be able to retrieve the actual request-timestamp from the HttpContext or HttpRequest , but it doesn't look like there's a property available which contains this value.

Therefore, I think RequestTrackingMiddleware must be modified, so that the date/time of the incoming request is stored in a variable before the remainder of the ASP.NET pipeline is executed. This variable can then be passed to the LogRequest method.
Something like this:

DateTimeOffset timestamp = DateTimeOffset.UtcNow;

try
{
    await _next(context);
}
finally
{
     _logger.LogRequest(timestamp, ..... );
}

I don't know what would be the best way to handle this to be honest: change the signature of the LogRequest method which would mean a breaking change ?
Or allow that this timestamp can be added to the LogContext dictionary, and retrieved from there. If it is not present, fall back to DateTimeOffset.UtcNow ?

Edit: this might be interesting:
https://stackoverflow.com/questions/46409709/where-is-httpcontext-timestamp-in-asp-net-core-mvc

Instead of adding the timestamp to the logContext dictionary, we can add it to the Items collection of the HttpContext.
We can retrieve it from there in Arcus.Observability, and if it is not present, use DateTimeOffset.Now like what is happening now.

[stijnmoreels]

I think this can be fixed by how we track Azure Service Bus requests, now. With the DurationMeasurement. We could add an overload with this type so that we can track and measure the HTTP request.

Nice catch! This was indeed something that was missing in our service-to-service correlation story, and will be great to have.

[stijnmoreels]

This update should be in observability, though, so if we agree on things, we can create an follow-up issue there.

[fgheysels]

I think it needs changes in both Observability and in the request-tracking middleware ?

[stijnmoreels]

I think it needs changes in both Observability and in the request-tracking middleware ?

Yes, indeed. Observability ->- Web API.

[stijnmoreels]

Hmm, the fix we need is not in Observability v2.4 because we chose .NET 6 support above this. Maybe we can create a fix-release. We already have added some minor new features since v2.4, like adding dependency ID's to Azure Search and Azure Service Bus Topic dependency tracking. So, maybe it should be called v2.5.

[fgheysels]

I agree with creating a fix release.

[stijnmoreels]

I agree with creating a fix release.

Wouldn't a fix release be wrong, as there are already new features on master? I guess there are other things that needs to be added too, to the observability; like other fixes on Azure Functions arcus-azure/arcus.observability#364). We may choose to wait until there's a better/full minor version for this.
Plus, we have the same issue with Web API. We will have other fixes here as well.