Introduction

On my current project a number of clients have asked to be able to track what their users were doing with the company’s data. At the time for the first request, the application captured some metadata, like dates and user, on key actions such as user account creation or deletion. We also had logging for the longer running and complicated calculations and imports but we had no generic universal auditing framework in place.

In any IT system being able to provide a record of who interacted with the system and when the data was changed is invaluable for troubleshooting and answering various questions such as:

  • Which user was accessing the system and when?
  • Who updated this property value and when?
  • What was the previous value before it was updated?
  • What actions has this user taken recently?
  • Who deleted this record?

The requirement from the various clients for the auditing was very generic, so we opted for the most basic solution which would capture the data required to answer the above questions and others like it. We also wanted to be able to add this auditing for our entire system and not just specific user registrations.

Message Handlers

Our website is built off a C# WebApi backend so we looked at how to leverage the existing pipeline. The best idea we found was to use Message Handlers as it allows us to intercept both the incoming request and the outgoing response. This allows us to capture all the data at the lowest level for an action and user who initiated that action.

Based off the implementations and notes from here, here and here, we got a basic version working that captured the relevant data. This is shown below:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
public class ApiLogHandler : DelegatingHandler
{
    private static JsonSerializerSettings settings = new JsonSerializerSettings()
    {
        ReferenceLoopHandling = ReferenceLoopHandling.Ignore,
        Formatting = Formatting.None
    };

    #region Protected Methods

    protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
    {
        var apiLogEntry = CreateApiLogEntryWithRequestData(request);
        if (request.Content != null)
        {
            request.Content.ReadAsByteArrayAsync()
                .ContinueWith(task =>
                {
                    apiLogEntry.RequestContentBody = System.Text.UTF8Encoding.UTF8.GetString(task.Result);
                }, cancellationToken);
        }

        // Execute the request, this does not block
        var response = base.SendAsync(request, cancellationToken);

        response.ContinueWith(async (responseMsg) =>
        {
            var responseResult = responseMsg.Result;

            try
            {
                if (apiLogEntry != null)
                {
                    apiLogEntry.ResponseStatusCode = (int)responseResult.StatusCode;
                    apiLogEntry.ResponseTimestamp = DateTime.Now;

                    if (responseResult.Content != null)
                    {
                        apiLogEntry.ResponseContentBody = await responseResult.Content.ReadAsStringAsync();
                        apiLogEntry.ResponseContentType = responseResult.Content.Headers.ContentType.MediaType;
                        apiLogEntry.ResponseHeaders = SerializeHeaders(responseResult.Content.Headers);
                    }

                    // TODO: Save the API log entry to the database

                    var filename = string.Format("{0}\\{1}_{2:yyyyMMdd-HHmmss-fff}.json", @"C:\Temp\APILogs", apiLogEntry.RequestId, apiLogEntry.RequestTimestamp);
                    System.IO.File.WriteAllText(filename, JsonConvert.SerializeObject(apiLogEntry, settings));
                }
            }
            catch (Exception ex)
            {
                // TODO: Log exception here
            }
        });

        return response;
    }

    #endregion

    #region Private Methods

    private ApiLogEntry CreateApiLogEntryWithRequestData(HttpRequestMessage request)
    {
        var context = ((HttpContextBase)request.Properties["MS_HttpContext"]);
        var routeData = request.GetRouteData();

        var entry = new ApiLogEntry
        {
            Application = Config.APILoggingApplication,
            UserId = context.User.Identity.GetUserId(),
            RequestId = request.Headers.GetRequestId(),
            Machine = Environment.MachineName,
            RequestContentType = context.Request.ContentType,
            RequestIpAddress = context.Request.UserHostAddress,
            RequestMethod = request.Method.Method,
            RequestHeaders = SerializeHeaders(request.Headers),
            RequestTimestamp = DateTime.Now,
            RequestUri = request.RequestUri.ToString()
        };

        return entry;
    }

    private string SerializeRouteData(IHttpRouteData routeData)
    {
        return JsonConvert.SerializeObject(routeData, settings);
    }

    private string SerializeHeaders(HttpHeaders headers)
    {
        var dict = new Dictionary<string, string>();

        foreach (var item in headers.ToList())
        {
            if (item.Value != null)
            {
                var header = String.Empty;
                foreach (var value in item.Value)
                {
                    header += value + " ";
                }

                // Trim the trailing space and add item to the dictionary
                header = header.TrimEnd(" ".ToCharArray());
                dict.Add(item.Key, header);
            }
        }

        return JsonConvert.SerializeObject(dict, settings);
    }

    #endregion
}

The handler is registered as the first handler in the pipeline as shown below:

1
2
/// In App_Start/WebApi.config.cs
config.MessageHandlers.Add(new ApiLogHandler());

However we also needed the handler to work with our existing dependency injection framework, Unity, so we could inject a service to persist the logged data.

The answer to this problem lies in how message handlers work and how they are registered. Each message handler is daisy chained in order of registration in the pipeline of execution. So the incoming request will be processed in one direction and the outgoing response will be processed in the reverse order. The diagram below illustrates this flow:

Message Handlers

This order of registration allows us to create another handler which can act as wrapper or proxy to any other handler, and so trigger the creation of the dependency injected scope.

The code for this wrapper is shown below (courtesy of StackOverflow):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
/// <summary>
/// Proxy class for delegating handlers using unity
/// Taken from: http://stackoverflow.com/a/26472999/2090108
/// </summary>
/// <typeparam name="TDelegatingHandler"></typeparam>
public class DelegatingHandlerProxy<TDelegatingHandler> : DelegatingHandler where TDelegatingHandler : DelegatingHandler
{
    private readonly IUnityContainer container;

    public DelegatingHandlerProxy(IUnityContainer container)
    {
        this.container = container;
    }

    #region Protected Methods

    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
    {
        // trigger the creation of the scope.
        request.GetDependencyScope();

        // Do not use a "using" here, as we need this handler to only go out of scope when the container goes out of scope.
        var handler = this.container.Resolve<TDelegatingHandler>();
        handler.InnerHandler = this.InnerHandler;

        var invoker = new HttpMessageInvoker(handler);

        var response = await invoker.SendAsync(request, cancellationToken);

        return response;
    }

    #endregion
}

To take advantage of Unity and the DI life cycle, we now need to register the handler like this:

1
2
/// In App_Start/WebApi.config.cs
config.MessageHandlers.Add(new DelegatingHandlerProxy<APILogHandler>(container)); // container is the Unity container based into the Register function.

If you have more than one message handler, you will want to register the more important ones first.

Fast forward a few months, add some bug fixes and adaptations and the main SendAsync method now looks like this:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
    HttpResponseMessage response = null;
    APILogEntry apiLogEntry = null;

    try
    {
        apiLogEntry = CreateApiLogEntryWithRequestData(request);
        if (request.Content != null)
        {
            var requestBody = await request.Content.ReadAsStringAsync();

            requestBody = JsonSanitizer.SanitizeData(apiLogEntry.RequestContentType, requestBody);

            apiLogEntry.RequestContentBody = requestBody;
        }

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

        if (apiLogEntry != null)
        {
            if (response != null)
            {
                // If the user was not authenticated when the log entry was created, 
                // then try get the user details now.
                if (string.IsNullOrEmpty(apiLogEntry.UserId))
                {
                    HttpContextBase context = GetContextFromRequest(request);
                    string userId = context.User.Identity.GetUserId();
                    if (userId == null)
                    {
                        userId = "";
                    }
                    apiLogEntry.UserId = userId;
                }

                apiLogEntry.ResponseStatusCode = (int)response.StatusCode;
                apiLogEntry.ResponseTimestamp = DateTime.Now;
                apiLogEntry.ResponseHeaders = SerializeHeaders(response.Headers);

                if (response.Content != null)
                {
                    /*
                    * For some responses, it can only be read once.
                    * Making a copy of the content fixes that.
                    * http://stackoverflow.com/a/27300959/2090108
                    */
                    var ms = new System.IO.MemoryStream();
                    await response.Content.CopyToAsync(ms);
                    ms.Seek(0, System.IO.SeekOrigin.Begin);

                    var sr = new System.IO.StreamReader(ms);

                    var responseBody = sr.ReadToEnd();
                    var responseContentType = response.Content.Headers.ContentType.MediaType;
                    responseContentType = responseContentType == null ? "" : responseContentType;

                    responseBody = JsonSanitizer.SanitizeData(responseContentType, responseBody);
                    
                    apiLogEntry.ResponseContentBody = responseBody;
                    apiLogEntry.ResponseContentType = responseContentType;
                    apiLogEntry.ResponseContentHeaders = SerializeHeaders(response.Content.Headers);
                }

                try
                {
                    APILogWriter.WriteAPILogEntry(apiLogEntry);
                }
                catch (Exception ex)
                {
                    LogHandler.LogError("Failed to write api request and response to database", ex);
                }
            }
            else
            {
                try
                {
                    apiLogEntry.ResponseTimestamp = DateTime.Now;
                    apiLogEntry.ResponseContentBody = "Response is null";
                    apiLogEntry.ResponseStatusCode = 500;
                    APILogWriter.WriteAPILogEntry(apiLogEntry);
                }
                catch (Exception ex)
                {
                    LogHandler.LogError("Failed to write api request to database", ex);
                }
            }
        }
    }
    catch (TaskCanceledException tex)
    {
        WriteApiLogEntryFromException(apiLogEntry, tex);
        throw;
    }
    catch (OperationCanceledException opex)
    {
        WriteApiLogEntryFromException(apiLogEntry, opex);
        throw;
    }
    catch (Exception ex)
    {
        WriteApiLogEntryFromException(apiLogEntry, ex);
        throw;
    }

    return response;
}

Leasons learned

A couple of points worth mentioning:

  • We have changed to use the await keyword as we found this to be more suitable, and easier to understand for the flow. At each point we have to block to wait for other process to complete, so why not make it clearer?
  • We make a copy of the response stream after the outgoing response has been created, to avoid any access issues on the client side.
  • The APILogWriter is an injected object that uses ADO.NET to write to our logging database, and will gracefully log any errors and suppress exceptions.
  • The LogHandler is an injected object used to log any messages via our logging framework (in this case NLog).
  • On the initial deployment we were logging passwords…. in clear text…. erk! So we added the SanitizeData method to clean up the data.

The workings behind the SanitizeData method require a little detail to be provided. Basically the method scans the input string and replaces the data for any sensitive fields with a custom token. If the input string is valid JSON, then the SanitizeJSONStringOfSensitiveFields method is called, otherwise the SanitizeStringOfSensitiveFields method is called. The list of SensitivePropertiesToRemove includes “password”, “oldPassword” and “newPassword” but you can include any property names that need to be scrubbed.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
/// <summary>
/// Remove sensitive data from the JSON string.
/// </summary>
/// <param name="json"></param>
/// <returns></returns>
private static string SanitizeJSONStringOfSensitiveFields(string json)
{
    var jArr = JToken.Parse(json);
    JToken blank = JToken.FromObject(SensitivePropertiesReplacementString);

    foreach (var property in SensitivePropertiesToRemove)
    {
        jArr.Children().OfType<JProperty>()
            .Where(p => p.Name == property)
            .ToList()
            .ForEach(att => att.Value = blank);
    }

    return jArr.ToString(Formatting.None);
}

/// <summary>
/// Remove sensitive properties from a string.
/// </summary>
/// <param name="inputString"></param>
/// <returns></returns>
private static string SanitizeStringOfSensitiveFields(string inputString)
{
    /*
    * Adapted from https://stackoverflow.com/q/11052744
    */
    var result = inputString;

    if (inputString.Contains("&"))
    {
        result = "";
        var queryStringParts = inputString.Split(new[] { '&' });

        for (int index = 0; index < queryStringParts.Length; index++)
        {
            var keyValue = queryStringParts[index].Split(new char[] { '=' });
            var key = keyValue[0];
            var value = keyValue[1];

            foreach (var property in SensitivePropertiesToRemove)
            {
                if (property == key)
                {
                    value = SensitivePropertiesReplacementString;
                    break;
                }
            }

            if (index != 0)
            {
                result += "&";
            }

            result += string.Format("{0}={1}", key, value);
        }
    }

    return result;
}

Insights gained

The data gathered from this audit logging has proved very useful on a number of occasions. We have had clients query which users changed the data and when, and we have been able to provide explanations for how and when things happened.

An additional unintended benefit of this data is that we have been able to track and monitor the performance of our websites, and identify and troubleshoot slower running api calls.

Based on the captured data, over the last 135 days the main web application has handled 2 877 435 web API requests from 3065 unique IP addresses. Of those total number of requests 98.59 % had a 200 response code, a further 0.30 % of the requests were 400 response codes (attempting to save bad data etc) and only 0.03 % of the requests were 500 server side errors. The average response time of the processing of a successful request on the server was 332 milliseconds, which I believe indicates we are running fairly well.

The full data set is shown below:

Audit Data Results

Conclusion

The output of this audit logging has been very valuable to the project and the client, and I hope you will find it useful too. Our next steps will be to extract and transform this data into a live monitoring tool for display on our Build Monitors. Further refinement of the data extraction and combined with a live chat tool built into the website will allow our Support team to proactively contact users when they need assistance.

Please drop me a line if you have any questions, or just let me know if you are doing something similar, I would love to hear about it.