Telemetry Initializer to add request body content from .net core MVC app to request telemetry properties not working

[balakrishnanj]

I'm trying to integrate application insights to .net core MVC application. Everything worked as expected till I added a telemetry initializer to read request body content. I created a ITelemetryInitializer which reads the content from the request body if the telemetry type is request telemetry. But i'm getting "System.ObjectDisposedException: 'Cannot access a disposed object.'" I tried adding Microsoft.ApplicationInsights.AspNetCore as project reference and even the pre-defined initializers are invoked after the action method.

Issue:

On debugging I noticed, when a POST/PUT http call is made, MVC action method is invoked before Initialize() method. So by the time the Initialize() method is invoked, request body request stream is already disposed. I've a similar implementation for 4.6 framework web api application, but its works fine without this issue.

Is there a way I can invoke the initializers before MVC action is executed. I tried configuring application insights with IWebHostBuilder and IServiceCollection.

Did anyone come across this issue?

Version Info
SDK Version : 2.2.1
.NET Version : .Net core 2.0
How Application was onboarded with SDK(VisualStudio/StatusMonitor/Azure Extension) :
OS :
Hosting Info (IIS/Azure WebApps/ etc) : IIS

[cijothomas]

@balakrishnanj It is not possible to read the Post/Put body stream twice - so attempting to read it in TelemetryInitializer is not recommended and will fail.

If your intention is to populate/enrich RequestTelemetry with some information from the request body, then the following approach is recommended:
Inside your controller, you can get a hold of the RequestTelemetry object.
RequestTelemetry requestTelemetry = HttpContext.Features.Get<RequestTelemetry>();

And you can enrich this requestTelemetry using any values available to your controller. (which includes the request body as well). The following shows a full example

[HttpPost]
        public IActionResult Create([FromBody] TodoItem item)
        {
            if (item == null)
            {
                return BadRequest();
            }

            RequestTelemetry requestTelemetry = HttpContext.Features.Get<RequestTelemetry>();
            requestTelemetry.Properties.Add("cijokey", item.Name);

            _context.TodoItems.Add(item);
            _context.SaveChanges();

            return CreatedAtRoute("GetTodo", new { id = item.Id }, item);
        }

PLease let us know if this helps!
Big thanks to @lmolkova for helping me understanding this!

[cijothomas]

posted the same in SO as well
https://stackoverflow.com/questions/50280933/telemetry-initializer-to-add-request-body-content-from-net-core-mvc-app-to-requ

[lmolkova]

@balakrishnanj
I noticed that on stackoverflow you posted code that uses EnableRewind method - thanks for educating me on this!
It seems this method is not working as expected, see more (and workarounds) in aspnet/Mvc#4962.

The @cijothomas's approach saves you one extra stream reading. Also, you can add extra properties only in the controller methods where requests suppose to have the body.

[cijothomas]

@balakrishnanj please reopen if you have more questions about this.

[daspoon]

"It is not possible to read the Post/Put body stream twice" is not accurate -- the decision to dispose the request body stream prior to invoking telemetry initializers is what prevents reading the body content. The suggestion to capture request bodies in controllers is not feasible -- why should all relevant endpoints be complicated with code to enable a feature clearly in the domain of middleware? Discussion on stack overflow (https://stackoverflow.com/a/42772603) suggests the OP's approach used to work -- now achieving this effect would require middleware to capture all request body content (as opposed to that of failed requests) and plumbing to make that content available in the telemetry initializer. This is a bug, imo.

[michaeltnguyen]

@daspoon is spot on. While HttpContext.Request.EnableBuffering() does allow the body to be read multiple times, that technique does not work because the request body is disposed by the time telemetry initializers are run. Here's an implementation that works, but feels like a giant hack.

// like IHttpContextAccessor, but for accessing the http body after the stream has been disposed.
// since the server can be handling multiple requests simultaneously, map the http body to the
// HttpContext.traceInitializer.  This is similar to how IHttpContextAccessor works.
public interface IHttpBodyAccessor {
    string GetHttpBody(string traceInitializer);
    string SetHttpBody(string traceInitializer, string body);
}

// Read the request body before it is processed, and store it in an IHttpBodyAccessor
public class EnableRewindMiddleware
    {
        private readonly RequestDelegate _next;

        public EnableRewindMiddleware(RequestDelegate next)
        {
            _next = next;
        }

        public async Task Invoke(HttpContext context, IHttpBodyAccessor bodyAccessor)
        {
            context.Request.EnableBuffering();

            // keep the stream open
            using (var reader = new StreamReader(context.Request.Body, Encoding.UTF8, true, 1024, true))
            {
                bodyAccessor.SetHttpBody(context.TraceIdentifier, reader.ReadToEnd());
            }
            // reset the position for the next reader (i.e., the controller)
            context.Request.Body.Position = 0;

            await _next(context);
        }
    }

public class CustomDataTelemetryInitializer : ITelemetryInitializer
    {
        private readonly IHttpContextAccessor _httpContextAccessor;
        private readonly IHttpBodyAccessor _httpBodyAccessor;

        public CustomDataTelemetryInitializer(
            IHttpContextAccessor contextAccessor, IHttpBodyAccessor bodyAccessor)
        {
            this._httpContextAccessor = contextAccessor;
            this._httpBodyAccessor = bodyAccessor;
        }

        public void Initialize(ITelemetry telemetry)
        {
            var requestTelemetry = telemetry as RequestTelemetry;
            if (requestTelemetry != null && requestTelemetry.Success == false)
            {
                var context = _httpContextAccessor.HttpContext;
                // can't read from the request body at this point, as the
                // request stream has already been disposed.
                string body = _httpBodyAccessor.GetHttpBody(context.TraceIdentifier);
                if (!string.IsNullOrEmpty(body))
                {
                    requestTelemetry.Properties.Add("RequestBody", body);
                }
            }
        }
    }

[daspoon]

@cijothomas Please re-open this issue in light of the above comments. Thank you.

[alexsandro-xpt]

@michaeltnguyen if I want to get the ResponseBody in requestTelemetry.Success == false scenary, I should do an ASPNet ActionFilter or a Response Middleware?

[zamzowd]

I'm reluctant to go with @michaeltnguyen's workaround described above, because I don't have a good way to remove items in the dictionary supporting IHttpBodyAccessor. I tried using AsyncLocal, but apparently the TelemetryInitializer isn't run in the same async context as the middleware (the value is always null when read in the TelemetryInitializer). The Response.RegisterForDispose is similarly triggered before the TelemetryInitializer, so I can't rely on that for cleaning up the dictionary.

Since this is more about the AspNetCore EndRequest event, I created a new issue describing this: dotnet/aspnetcore#9258

[michaeltnguyen]

@zamzowd You could remove the item in the ITelemetryInitializer after you add it to the RequestTelemetry Properties. Alternatively, if you implement the IHttpBodyAccessor using an LRU Cache, your old items will automatically be removed based on whatever capacity you set.

[zamzowd]

@michaeltnguyen I considered having the record removed when it's read. I was concerned that I might end up with records added that never get read for some reason, but didn't set up a proof-of-concept to see if that would actually happen.

I haven't considered using a cache, I might try that out.

[ThiruKM]

I solved using the following approach and explained the same in the following blog, This is similar to michaeltnguyen idea but bit different in approach.

https://thirum.wordpress.com/2019/08/19/logging-the-http-response-body-in-application-insights/

My idea is to record the response using a delegate handler since the response object is not disposed at the stage of the message handler. The message handler is part of the Web API life cycle i.e. similar to the HTTP module but confined to Web API Life cycle. When I developed and tested this idea, fortunately, It worked I recorded the response in the request message using message handler and retrieved it at the AzureInitializer (HTTP module whose execution happens later than the message handler i.e ASP.NET Web API Life cycle order). Here is the sample code.

public class AzureRequestResponseInitializer : ITelemetryInitializer
{
public void Initialize(ITelemetry telemetry)
{
var requestTelemetry = telemetry as RequestTelemetry;
if (requestTelemetry != null && HttpContext.Current != null && HttpContext.Current.Request != null)
{
if ((HttpContext.Current.Request.HttpMethod == HttpMethod.Post.ToString()
|| HttpContext.Current.Request.HttpMethod == HttpMethod.Put.ToString()) &&
HttpContext.Current.Request.Url.AbsoluteUri.Contains("api"))
using (var reader = new StreamReader(HttpContext.Current.Request.InputStream))
{
HttpContext.Current.Request.InputStream.Position = 0;
string requestBody = reader.ReadToEnd();
if (requestTelemetry.Properties.Keys.Contains("requestbody"))
{
requestTelemetry.Properties["requestbody"] = requestBody;
}
else
{
requestTelemetry.Properties.Add("requestbody", requestBody);
}
}
else if (HttpContext.Current.Request.HttpMethod == HttpMethod.Get.ToString()
&& HttpContext.Current.Response.ContentType.Contains("application/json"))
{
var netHttpRequestMessage = HttpContext.Current.Items["MS_HttpRequestMessage"] as HttpRequestMessage;
if (netHttpRequestMessage.Properties.Keys.Contains("responsejson"))
{
var responseJson = netHttpRequestMessage.Properties["responsejson"].ToString();
if (requestTelemetry.Properties.Keys.Contains("responsebody"))
{
requestTelemetry.Properties["responsebody"] = responseJson;
}
else
{
requestTelemetry.Properties.Add("responsebody", responseJson);
}
}
}
}

}

}

config.MessageHandlers.Add(new LoggingHandler());
public class LoggingHandler : DelegatingHandler
{
protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
return base.SendAsync(request, cancellationToken).ContinueWith(task =>
{
var response = task.Result;
StoreResponse(response);
return response;
});
}

private void StoreResponse(HttpResponseMessage response)
{
    var request = response.RequestMessage;

    (response.Content ?? new StringContent("")).ReadAsStringAsync().ContinueWith(x =>
    {
        var ctx = request.Properties["MS_HttpContext"] as HttpContextWrapper;

        if (request.Properties.ContainsKey("responseJson"))
        {
            request.Properties["responsejson"] = x.Result;
        }
        else
        {
            request.Properties.Add("responsejson", x.Result);
        }
    });
}

}

[IanKemp]

For .NET Core you don't need an ITelemetryInitializer implementation at all, just the middleware to pull the request and/or response body(ies) out of the supplied HttpContext. In that middleware, simply get the RequestTelemetry from the supplied HttpContext.Features, then enrich its properties with the body data:

public async Task InvokeAsync(HttpContext context)
{
    var request = context.Request;

    if (request?.Body?.CanRead == true)
    {
        request.EnableRewind();

        var bodySize = (int)(request.ContentLength ?? request.Body.Length);
        if (bodySize > 0)
        {
            request.Body.Position = 0;

            byte[] body;

            using (var ms = new MemoryStream(bodySize))
            {
                await request.Body.CopyToAsync(ms);

                body = ms.ToArray();
            }

            request.Body.Position = 0;

            var requestTelemetry = context.Features.Get<RequestTelemetry>();
            if (requestTelemetry != null)
            {
                var requestBodyString = Encoding.UTF8.GetString(body);

                requestTelemetry.Properties.Add("RequestBody", bodyString);
            }
        }
    }

    await _next(context);
}

[zamzowd]

@IanKemp I didn't know the RequestTelemetry can be retrieved like that. This approach works quite well, thanks.

[ThiruKM]

@IanKemp Thanks for letting us know. It seems to work on the .NET core but not on ASP.NET 4.6(WEB API). Mine is not on core yet. It seems we have limited capability on the traditional .NET side.

[cijothomas]

@ThiruKM try var requestTelemetry = HttpContext.Current?.GetRequestTelemetry().
In both ,net and .net core, its possible to retrieve RequestTelemetry and enrich it right inside the controller.
This is an internal implementation details, and not publicly documented in docs page.

[ThiruKM]

@cijothomas Thanks for responding. My web services are not .NET Core it is on .NET 4.6 - Web api but I went ahead I tried using the above code unfortunately it returned null as pictured below

[cijothomas]

Please share a full sample.
In the screenshot, is .Current null? or GetRequestTelemetry() is returning null?

[ThiruKM]

@cijothomas It is current that is null. It is on my production code. I am not allowed to share the code but if you want I need to write an sample.

[cijothomas]

Where is this code running? I mean is it inside a TelemetryInitializer? And is httpcontext.current null for RequestTelemetry? or some other telemetry?
A full example would help, but the above questions would really help as well.

[ThiruKM]

It is part of DelegatingHandler as part of the following method.

protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)

[cijothomas]

okay. I am not an expert here, so not sure why context is null there.
You'll need to find the place in pipeline where context will be available, and retrieve/enrich Requesttelemetry.

We have been receiving a lot of requests about how to log request/response body. There will be a official way to achieve this.
cc: @Dawgfan I believe you had a similar item in our last planning meeting.

[ThiruKM]

@cijothomas @Dawgfan Thx for spending some time. I have a work around as mentioned in my blog for now. Happy to wait for the official solution.

[IanKemp]

We have been receiving a lot of requests about how to log request/response body. There will be a official way to achieve this.

Please yes.

[kendaleiv]

@cijothomas Any update to share on timing of logging request bodies in an officially supported capacity?

[cijothomas]

We did not have resource to tackle this in 2019. @Dawgfan has this as one of the top items to handle in 2020.