During load testing last week, we had a situation where our Json requests were failing and the exceptions that were logged did not contain enough information. We suspected that the raw JSON payload was incorrect, as it was being generated by a Performance Testing Scripting tool, rather than the browser directly.

Exceptions like the following were showing up in the logs:

System.ArgumentException: Invalid JSON primitive: quoteNo.
  at System.Web.Script.Serialization.JavaScriptObjectDeserializer.DeserializePrimitiveObject()
  at System.Web.Script.Serialization.JavaScriptObjectDeserializer.DeserializeInternal(Int32 depth)
  at System.Web.Script.Serialization.JavaScriptObjectDeserializer.DeserializeDictionary(Int32 depth)
  at System.Web.Script.Serialization.JavaScriptObjectDeserializer.DeserializeInternal(Int32 depth)
  ...

In order to capture the raw JSON payload, we initially used Troubleshooting Failed Requests Using Tracing in IIS 7, with the trace provider “WWW Server” set to Verbose logging for a specific controller action, with a 200 status code. While this worked, it was cumbersome to setup and it was difficult to relate each request exception to the correct JSON payload.

As we needed a more long term, robust solution, we instead looked to log the data when the exception occured. We then updated our base controller with more specific exception handling, as 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
protected override void OnException(ExceptionContext filterContext)
{
    if (filterContext.Exception != null &&
            filterContext.RequestContext.HttpContext.Request.IsAjaxRequest())
    {
        var exception = filterContext.Exception;
        filterContext.ExceptionHandled = true;
        filterContext.HttpContext.Response.Clear();
        filterContext.HttpContext.Response.TrySkipIisCustomErrors = true;
        filterContext.HttpContext.Response.StatusCode =
                    (int)System.Net.HttpStatusCode.InternalServerError;
        var guidId = Guid.NewGuid();
        var errorMsg = String.Format("An error has occurred. Error ID {0}",
                                        guidId.ToString());
        filterContext.Result = new JsonResult
        {
            Data = new { Error = errorMsg },
            JsonRequestBehavior = JsonRequestBehavior.AllowGet
        };
        LogHandler.LogError(String.Format("Ajax Exception: {0}, GUID: {1}",
                exception.Message, guidId.ToString()), exception);

        if (filterContext.HttpContext.Request.ContentType.Contains("application/json"))
        {
            try
            {
                string rawJSONString;
                Stream req = filterContext.HttpContext.Request.InputStream;
                req.Seek(0, System.IO.SeekOrigin.Begin);
                using (var sr = new StreamReader(filterContext.HttpContext.Request.InputStream))
                {
                    rawJSONString = sr.ReadToEnd();
                }

                if (!String.IsNullOrEmpty(rawJSONString))
                {
                    LogHandler.LogDebug(String.Format("JSON Payload for GUID {0}: \"{1}\"",
                                            guidId.ToString(), rawJSONString));
                }
                else
                {
                    LogHandler.LogDebug(String.Format("JSON Payload for GUID {0} was null or empty.",
                                            guidId.ToString()));
                }
            }
            catch (Exception ex)
            {
                LogHandler.LogError(
                    String.Format("Failed to get JSON payload. Exception: {0}",
                                    ex.Message), ex);
            }
        }
    }
}

In our log files we now have the full exception as well as the payload that caused the exception, linked by an error GUID:

2014-09-11 15:08:14,401 ERROR [6] Ajax Exception: Invalid JSON primitive: clientId., GUID: 9a1f4493-a176-4e3d-8140-b2d4742805e9 
System.ArgumentException: Invalid JSON primitive: clientId.
   at System.Web.Script.Serialization.JavaScriptObjectDeserializer.DeserializePrimitiveObject()
   at System.Web.Script.Serialization.JavaScriptObjectDeserializer.DeserializeInternal(Int32 depth)
   ....
2014-09-11 15:08:26,554 DEBUG [6] JSON Payload for GUID 9a1f4493-a176-4e3d-8140-b2d4742805e9: 
    {"TitleSequenceNo":1,"FirstName1":"John","FirstName2":"","FirstName3":"","FirstName4":"","FirstName5":"",
        "Surname":"Abavus","DateOfBirth":"1925-05-15T00:00:00","GenderSequenceNo":3,
        "SmokerIndicator":0,"MaritalStatusSequenceNo":4,"ClientId":clientId,"ViewModelType":1} 

Troubleshooting just became a whole lot easier! :)



This post was originally published on Entelect’s internal Tech Blog, Yoda.