ASP.NET Web API Logging Inbound Request Content

Question

I’m trying to log out Web API Request Content – i.e. the json string. I implemented an ITraceWriter class (example) and configured it so that Web API calls it in the pipeline. But if I read the request.Content or copy into to a stream to read it is not available for the method resulting in a null model. This post talks about that issue a little. Anyone have experience logging out inbound Web API request content and know what the best approach is?

Thanks

Update A

I created a simple sample Web API project to rule out anything in my project and I still see that the model will be null because of logging. I simply test a few times in a row by posting via Fidder and see my model comes in null. With breakpoints in place, it might work which is why I think there is a sync/timing issue. Any thoughts on how to get this to work?

Header:

User-Agent: Fiddler
Host: localhost:56824
Content-Type: application/json
Content-Length: 22

Body:

{
"A":1,"B":"test"
}

Here's the code:

Controller:

public class ValuesController : ApiController
{
    [HttpPost]
    public void Post(ValuesModel model)
    {
        if (model == null)
        {
            Debug.WriteLine("model was null!");
        }
        else
        {
            Debug.WriteLine("model was NOT null!");
        }
    }
}

Model:

public class ValuesModel
{
    public int A { get; set; }
    public string B { get; set; }
}

Logger:

public class APITraceLogger : DelegatingHandler
    {
        protected override System.Threading.Tasks.Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
        {
            if (request.Content != null)
            {
                // This can cause model to be null
                request.Content.ReadAsStringAsync().ContinueWith(s =>
                {
                    string requestText = s.Result;
                    Debug.WriteLine(requestText);
                });

                // and so can this
                //request.Content.ReadAsByteArrayAsync()
                //    .ContinueWith((task) =>
                //    {
                //        string requestText = System.Text.UTF8Encoding.UTF8.GetString(task.Result);
                //        Debug.WriteLine(requestText);
                //    });
            }
            // Execute the request, this does not block
            var response = base.SendAsync(request, cancellationToken);

            // TODO:
            // Once the response is processed asynchronously, log the response data
            // to the database


            return response;
        }


    }

Wiring up logger in WebApiConfig class:

config.MessageHandlers.Add(new APITraceLogger());

Update B

It seems like it is now working if I change the logger to the following code adding the await, async and returning the result. Seems like something I'm not understanding in the async code or truly a timing issue or something.

public class APITraceLogger : DelegatingHandler
{
    protected async override System.Threading.Tasks.Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
    {
        if (request.Content != null)
        {

            // This does seem to work - is it because it is synchronous?  Is this a potential problem?
            var requestText = await request.Content.ReadAsStringAsync();
            Debug.WriteLine(requestText);
        }
        // Execute the request, this does not block
        var response = base.SendAsync(request, cancellationToken);

        // TODO:
        // Once the response is processed asynchronously, log the response data
        // to the database


        return response.Result;
    }


}

Answer 1

As Filip mentions in that post ReadAsStringAsync or ReadAsByteArrayAsync methods buffer the request content internally. This means that even if your incoming request's stream type is a non-buffered stream, you could safely do a ReadAsStringAsync/ReadAsByteArrayAsync at a message handler for example, and also expect the model binding to work fine.

By default, a request's stream is buffered in both webhost and selfhost cases. But if you would like to check if using ReadAsStringAsync/ReadAsByteArrayAsync and model biding works fine even in non-buffered mode, you can do the following to force non-buffered mode:

public class CustomBufferPolicySelector : WebHostBufferPolicySelector
{
    public override bool UseBufferedInputStream(object hostContext)
    {
        //NOTE: by default, the request stream is always in buffered mode.
        //return base.UseBufferedInputStream(hostContext);

        return false;
    }
}

config.Services.Replace(typeof(IHostBufferPolicySelector), new CustomBufferPolicySelector());

Just FYI...the above policy selector works only for Web Host currently. If you would like to do a similar test in SelfHost, then do the following:

//NOTE: by default, the transfer mode is TransferMode.Buffered
config.TransferMode = System.ServiceModel.TransferMode.StreamedRequest;

After Update B of the post above:

You could modify your handler like below:

public class LoggingHandler : DelegatingHandler
{
    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
    {
        if (request.Content != null)
        {
            string requestContent = await request.Content.ReadAsStringAsync();
        }

        HttpResponseMessage response = await base.SendAsync(request, cancellationToken);

        if (response.Content != null)
        {
            string responseContent = await response.Content.ReadAsStringAsync();
        }

        return response;
    }
}