Logging requests and responses in a WebApiController

[gabriele-ricci-kyklos]

Is your feature request related to a problem? Please describe. I didn't find a way to automatically log request / response of a controller class in a Web API. I saw some logging done by the lib itself, but no way to customize it at a lower level

Describe the solution you'd like Some events for request / response in order to attach my logic when a request is processed or a response is sent

Describe alternatives you've considered The alternative is add logging in each method I write in my WebAPI

[rdeago]

Hello @gabriele-ricci-kyklos, thanks for using EmbedIO!

Although there is no way to customize what EmbedIO logs at the beginning and end of its request handling procedure, there may be a simpler workaround than adding logging to every controller method.

For example, you may override OnBeforeHandler in your controller to:

• log whatever you need just before the relevant controller method is called;
• call HttpContext.OnClose to install a callback that will be called when the response is sent, where you can log whatever you need.

What cannot really be done is log something when EmbedIO starts sending the response. This is a limitation EmbedIO inherits from HttpListener.

I hope you find this information useful. Please let us know whether this solves your problem, or if you need more assistance.

[gabriele-ricci-kyklos]

Hi @rdeago, thanks for the quick reply. I implemented OnBeforeHandler successfully, while I'm wondering where to put the HttpContext.OnClose, is it correct to be controller-side? Moreover I just noticed that also exceptions are not logged, I'm sure there's a way of handling that as well.

[rdeago]

The callback you pass to OnClose may well be a private method of your controller, or a lambda. Just be aware that if your controller class implements IDisposable the callback will be called after Dispose. The reason for this is that the controller's lifetime is entirely within the request handler of your WebApiModule, while close callbacks are called after module processing is finished.

I just noticed that also exceptions are not logged

Now this may be a bug. Can you describe the situation in more detail?

[gabriele-ricci-kyklos]

Now this may be a bug. Can you describe the situation in more detail?

I'm sorry, this was a bug of my implementation of ILogger for logging with NLog.

The callback you pass to OnClose may well be a private method of your controller

That's ok but where do I put the call to HttpContext.OnClose? I tried in the controller constructor but HttpContext is null.

[rdeago]

[...] where do I put the call to HttpContext.OnClose? I tried in the controller constructor but HttpContext is null.

Just put it in OnBeforeHandler. It is called after all controller's properties are initialized.

[gabriele-ricci-kyklos]

I created a private method

private async Task LogResponseAsync(IHttpContext context)
{
    if (context == null)
    {
        return;
    }

    using (Stream stream = context.OpenResponseStream())
    using (StreamReader streamReader = new StreamReader(stream))
    {
        string content = await streamReader.ReadToEndAsync().ConfigureAwait(false);
        _restLogger.Debug($"{context.Request.RawUrl} response: {content}");
    }
}

Then in OnBeforeHandler I added the OnClose callback

HttpContext.OnClose(async context => await LogResponseAsync(context).ConfigureAwait(false));

When I try I'm getting an error

System.ArgumentException: 'Stream was not readable.'

I see that HttpContext.OutputStream has CanRead property to false, so how can I read the response from HttpContext? Many thanks in advice

[rdeago]

how can I read the response from HttpContext?

You can't read the response stream, but you can hijack WebModuleBase's response serialization and log the response just before it is sent. You don't even need OnClose for that, because your code will be called when the response is ready, i.e. after the relevant controller method returns.

First, you need to define a response serialization callback. This is just a method, you can put it in a static class, like this:

using System;
using System.Threading.Tasks;
using EmbedIO;
using EmbedIO.Utilities;

namespace YOUR_APPLICATION
{
    public static class LoggingResponseSerializer
    {
        public static async Task Json(IHttpContext context, object? data)
        {
            context.Response.ContentType = MimeType.Json;
            context.Response.ContentEncoding = WebServer.Utf8NoBomEncoding;
            var responseText = Swan.Formatters.Json.Serialize(data);
            $"[{context.Id}] Response: {responseText}".Info(nameof(LoggingResponseSerializer));
            await ResponseSerializer.None(context, responseText).ConfigureAwait(false);
        }
    }
}

Then, when initializing your web server, specify that you want to use your shiny new serializer:

            .WithWebApi("/path", LoggingResponseSerializer.Json, m => m
                .WithController<MyController>())

[gabriele-ricci-kyklos]

It works eventually. There are a few slightly different things:

• The method ResponseSerializer.None does not exist, I had to use ResponseSerializer.Json with data instead of responseText
• The var WebServer.Utf8NoBomEncoding does not exist, the type of context.Response.ContentEncoding is System.Text.Encoding

Complete code:

public static async Task LogResponseCallback(IHttpContext context, object data)
{
    context.Response.ContentType = MimeType.Json;
    context.Response.ContentEncoding = Encoding.UTF8;
    var responseText = Swan.Formatters.Json.Serialize(data);
    _restLogger.Info($"[{context.Id}] - {context.Request.RawUrl} response: {responseText}");
    await ResponseSerializer.Json(context, data).ConfigureAwait(false);
}

Thank you very much for your help

[rdeago]

@gabriele-ricci-kyklos sorry for the inconvenience. You're right, I was basing my answer upon the head of the v3.X branch, that contains some not-yet-released additions. Nice to know you've solved your problem anyway.

[gabriele-ricci-kyklos]

@rdeago I have a different problem now. I successfully implemented OnBeforeHandler by doing

protected override void OnBeforeHandler()
{
    var content = HttpContext.GetRequestBodyAsStringAsync().Result;
    //request logging
}

Then I try to get the request data in my controller method, I do

var request = 
    await HttpContext
        .GetRequestDataAsync<MyRequest>()
        .ConfigureAwait(false);

The request var here is null. This is an issue related to the underlying http request stream, in fact its position reaches the end when OnBeforeHandler is executed, and no data is read later when I call GetRequestDataAsync. I even tried to reset the position by doing HttpContext.Request.InputStream.Position = 0 but the CanSeek property is false so it can't be done.

I guess that the best workaround is to log the request in each controller method, but perhaps you have a different solution.

[rdeago]

The request stream can be consumed only once. If you read it with GetRequestBodyAsStringAsync, then GetRequestDataAsync has nothing left to read.

"You cannot fill a bottle with the same water you just drank." (nobody, actually - but you get the point)

The same would happen if you used any of the FormField, FormData, and JsonData attributes on parameters of your controller methods, as they too need to read the request stream.

Although you cannot read the same data twice (and you can't even rewind the request stream because it is a socket) you don't really need to: just store the result of GetRequestBodyAsStringAsync in a property of your controller, then parse it as needed.

private string RequestBody { get; set; }

protected override void OnBeforeHandler()
{
    RequestBody = HttpContext.GetRequestBodyAsStringAsync().Result;
    //request logging
}

    // ...then, in your request method, do the same thing GetRequestDataAsync does internally,
    // using the request body you already have instead of reading it from the request stream:
    var request = Swan.Formatters.Json.Deserialize<MyRequest>(RequestBody);

Your problem is solved. Yay for me!

Or is it?

You see, this way you make your code rather unusual and surprising for other EmbedIO users, including your future self. When you read that code in, say, one or two years, you're going to spend some precious minutes figuring out why you didn't use the recommended data attributes and such. If someone else has to maintain your code, and they've never seen an EmbedIO application, they'll find that quite a few examples in the documentation do not apply to your code; they could try to add a method to the controller by following the examples, just to find out that whoops! they can't use the JsonData attribute, for example.

My suggestion is to apply the principle of least astonishment: use request data attributes on your controller method parameters, or GetRequestDataAsync if you don't know the shape of the incoming JSON. You can use Wireshark on the server side and/or Fiddler on the client side to debug your server without even touching the code.

Of course there are exceptions, namely production software that is going to be run by customers, where you will occasionally have to log request bodies to debug some issue. No access rights to install Wireshark on the customer's machine, plus you know you're gonna be in a hurry, so logging request bodies from OnBeforeHandler could be the only way to go.

Even then, though, there's a better way. For example, create a subclass of WebApiController with your OnBeforeHandler override and RequestBody property (RequestCachingWebApiController could be a viable name) and create your own set of attributes implementing IRequestDataAttribute<TController> and/or IRequestDataAttribute<TController,TData>, to use on your controllers, getting data from RequestBody instead of trying to read the request stream. With little more than a bunch of cut-and-paste you'll get the best of both worlds. Bonus points if you put those shiny new classes in their own library.

---

On a side note, OnBeforeHandler returns void instead of Task precisely to discourage developers from doing anything time-consuming in it. By using Task.Result you sort of cheated: the thread that is serving the request will block until GetRequestBodyAsStringAsync returns. In this particular case there are no bad consequences, as you'd need to read the request stream anyway, but if I were to review your code that would stand out as a code smell anyway.

[gabriele-ricci-kyklos]

@rdeago thanks for your info. I had thought about your solution, in fact I created a base class for the OnBeforeHandler implementation, but what happens on multiple calls at the same time?

[rdeago]

Nothing special, actually. WebApiModule creates an instance of the relevant controller for every request; therefore, as long as you don't make RequestBody a static property, everything should work as described.

[gabriele-ricci-kyklos]

Great, then I'll definitely go with that implementation. Thank you very much for the help