New Web-related stuff - web service call logging and error handling

May 10, 2014 at 8:34 PM
Edited Jun 21, 2014 at 11:32 PM
Hi folks
Big news - first take on web-related functionality! New Vita.Modules.Web project and corresponding unit tests. Mostly the facilities concerned with diagnostics and logging for Web Api applicatons. These are first to come, as they should be - diagnostics first! Here is a quick overview, followed by explanation of problem points with ASP.NET Web Api that I'm trying to fix.

The classes in Vita.Modules.Web provide two logging facilitis - WebCallLog and ErrorLog. Both write log data to corresponding database tables. ErrorLog had been there for a while, but previously, you had to put explicit catch blocks in top controller methods and log exceptions from there; now after you setup Web api app properly, exceptions are logged automatically by LoggingMessageHandler.
WebCallLog logs information about every call to web service, at varying level of details. At Basic level, we log target URL (service end point), HTTP method, response status, time in ms spent in processing the request, controller and method names; user name, request/response size, client IP address and UrlReferrer (if available). At Details level, we additionally log input message and output message bodies (ex: json content in request body), request/response headers, plus SQL log containing all database calls happened during processing the request. If exception occurs, the error log record includes ID of the web log entry for this failed call, so you can easily find the details of the call.
Web log level (Basic/Detail) is set at startup. If you set it initially to Basic level, there are two ways it can be elevated to Details level. First, if the service call fails due to exception, the web log would write the information in Details mode, to save maximum information possible for the error. This happens if a special option is set during setup. The other case is using URL switch - if you add '_enablelog=true' to any call, the service will enable Detail level for this particular client (by IP address), until you set it back to false. This is mostly for use with UI apps that use JS queries to restful service to fill the data (ex: Single-page apps with AngularJS). Let's say a user reports that something does not work - no errors reported but the functionality is broken. It happens only for this user on a certain 'page'. So to investigate this, you ask the user to add 'enablelog=true' to any page URL and hit it (or do it yourself if you are there, or send her a link to hit). From this moment all calls to data services from java-script on the page have Detailed log level. As the user proceeds to do his troubled thing, you have a full detailed log on the server, including SQLs, with values and parameters, and you can investigate what's going on.
To sum it up - most likely usage scenario of web log is Basic by default, with automatic elevation to Details in case of error. This way you have basic statistics for all calls and can monitor server activities, without wasting too much space for logging all details. For errors, you have full information about the request.
I'd like to mention one important and really useful feature in error logging. MediaTypeFormatters are used in web api as serializers/deserializers of message contents - from/to xml/json to/from CLR objects. However, when formatter fails because of invalid input, it fails silently. It takes some effort to catch and log this error, and now MediaTypeFormatterSpy does this, for any actual formatter(s) you use.

Utility classes
There are a some utility classes there in Vita.Modules.Web. One is CheckModelAttribute - to automatically check if deserialization in type formatter fails and cancel the processing by throwing exception. By default, if deserializer fails, Web Api pipeline continues processing and still calls the controller method, with input parameter value set to null. You have to either manually add checks for nulls, or use the CheckModel attribute on controller method - then the check happens automatically.
The other utility class is HttpClientWrapper - it is a wrapper around HttpClient with a few convenient additions. Like Get<TResult>() method - with automatic deserialization of result objects and proper failure handling. It also injects spies for type formatters to properly catch deserialization failures. It handles properly the 'BadRequest' response (usually indicator of validation failures, invalid input) - and throws ValidationException with received error message. And some other useful stuff. The unit tests for web facilities use this wrapper to fire test calls to the service - see the code for the examples of use.

On the server side - one little nice facility - ability to set explicitly the Http status code for the response. The standard recipe in Web api is to use controller method returning HttpResponseMessage, instead of Dto object. That's the only way you can set the status other than OK (200). It means that you have to handle deserialization of results yourself (including content negotiation) - which breaks the Web api layer separation completely. This is in fact a very common situation; for example, for POST calls that supposedly create 'new resource' the service should return Created(201) status code. See unit test code (BookServiceController) for a really easy way to do this with VITA facilities.
WebHelper static class contains some useful static methods that might be helpful in many cases.

Unit tests for Web classes.
There is a new Vita.UnitTests.Web test project there, testing/showing how these new facilities work. The project includes a simple BookService - RESTful Web Api service - a controller, config class, and Dtos (Data Transfer Objects). Look at the code for an example of how easy it is to create a RESTful service, with access to database and solid diagnostics/error handling.
The unit test code initializes the service (server side) and then uses HttpClientWrapper to call it through HTTP. After the web calls it directly queries the 'server-side' database to check for the results of the call. It shows various scenarios (Get/Put/Post/Delete), with/without exceptions happening on the server, with automatic elevation of log level, and using URL switch.
May 10, 2014 at 8:36 PM
Edited May 10, 2014 at 8:40 PM
How it works
The central idea is the following - there's a WebCallInfo object, a container for all information about handling web request. It is created at the very beginning of processing inside LoggingMessageHandler and saved in request's properties dictionary under fixed key. It is available to any processing code in the pipeline, which in turn can fill out some fields in it. For example, the controller fills out the controller name and method name. Exceptions, if they happen in controller or type formatter, are saved in WebCallInfo as well. At the end of processing LoggingMessageHandler fills out the remaining pieces (like takes a copy of the response message), and logs the erros into ErrorLog and all other info into WebCallLog (if web call log is enabled).
Certain measures are taken for efficiency. WebCallLog is not written immediately - instead, log entries are accumulated in memory and then dumped once a second as a batch on a background thread. I'm talking about Batch Update mode (see previous post) - multiple log records are send as one SQL containing multiple calls to stored procedures. This is another strong case for Batch Update functionality - saving multiple log entries in one roundrip. Logging errors into error log on the other hand is done synchronously - this is too important data to wait and sit in memory with a risk of loss.
One 'unusual' case is TypeFormatter errors. It so happens that code spying on formatter and catching its errors does not have a reference to current request to retrieve WebCallInfo - to save the exception in it. It uses a static singleton dictionary to save exception temporarily, until it is retrieved later by error handling code in another layer/class.
Main handling classes:

LoggingMessageHandler - a 'top' level message listener. Responsible for creating WebCallInfo at the start of the call and saving all information when the call completes.

ExceptionHandlingFilter - handles exception; saves the exception in WebCallInfo object, formats output message and sets appropriate HTTP status code. Uses BadRequest (400) status code for ValidationExceptions - those that indicate invalid input by the users. The exception will be logged in LoggingMessageHandler.

MediaTypeFormatterSpy - a wrapper around MediaTypeFormatter, catches and saves formatter errors. It is a TypeFormatter subclass itself. You 'wrap' the real formatter inside formatter spy, and add it to TypeFormatters collection in Web Api.

CheckModelAttribute - an action filter attribute that previews the call to controller method and throws exception if there was an error in type formatter. Use it on controller methods that expect deserialized objects as parameter.
May 10, 2014 at 8:37 PM
Edited Jun 21, 2014 at 11:34 PM
How Web project evolved - some troubled history.
Like probably many of you, we've been using ASP.NET Web Api package for a while to build RESTful web services. Generally I like it, not quite love it - it has some quirks, but generally it works fine, relatively easy to setup and use.
But some problems emerged very early. One of the troubles was implementing proper diagnostics for web service applications. You can't go live if you don't a decent diagnostic facilities - error handling and logging. You don't have a Visual Studio debugger on a cloud server, so whenever something goes wrong - you must have enough information to deduce the cause of the crash. However, building a decent run-time diagnostics with Web Api is a bit of a pain. Ideally, these things should be configured at startup and work transparently, so that business logic (controllers) are free from extra handling code - this minimizes the overall effort plus protects you from invisible errors in error handlers sprinkled through business logic. But most of the demos/samples coming with Web Api actually suggest numerous logging calls or try/catch blocks throughout the mainstream code.
For our previous project we build a logging system. Here are some troubles we encountered. The recommended and simplest way to handle exceptions is through building ExceptionHandlingFilter and injecting it into a pipeline. The filter's OnException method gets called when exception is thrown in controller method. Great, we built a filter and log the exception into database. But then, wouldn't it be nice to also log the incoming parameters of the call, especially the serialized object in the body to make it easy to investigate the error? Yes, let's do that, but it turns out that Request's contents are not available. That is, you can grab Request stream and try to read it, but it turns it is 'read-once' and it is alreay been read. Bummer.. After some research we found out that you can re-read the stream, but only in another layer (higher) in handling pipeline. So here comes the custom message handler. Now you have problem of coordination between filter and message handler (on particular request!), and it is not so trivial, it requires some tricky coding.
Next - deserialization failures. Let's say your service expects a serialized object in message body which is deserialized and passed to the controller method as a parameter. If the incoming json/xml is invalid, you'll never know - your method receives null as an input object and no error information is lying around. Nowhere, none. IMHO, this is one of the most annoying troubles in ASP.NET web api. Mal-formed stuff happens, especially with Xml and all its xsd-conformance crap - the message looks ok, but deserializer says NO, does not conform.
It turned out there is a place where type formatters write errors, but it is not available through some event fired or something like this. To reach it programmatically you have subclass a few things, intercept the deserialization call and inject your own log listener into the process. We did this, and it worked, kinda, but the problem was the error message logged was not linked to any other information about the request. Even the contents of the message - nowhere to be retrieved for logging. The error was just sitting there in the database, and you had to manually pair it with other logs you hopefully had to figure out what's the problem. The other trouble is that if deserialization fails, the processing continues and your controller method is called, with null parameter value. We had to put checks for nulls at the beginning of controller methods and throw an exception to stop the nonsense. (Now you have CheckModel attribute which does the check automatically).
Finallly, logging web calls. Sooner or later you'll start thinking about it, and then you realize you absolutely need it. Just to know what's going on, to monitor basic activity and how much load your server has. Sometimes it is a 'legal' requirement from the very start - like with health/personal information you MUST have detailed log of external access and activities. The biggest problem is that the information you want to collect is available only in certain places in different layers of processing pipeline, and bringing it all together is not trivial. We did it from scratch, mostly at controller level, with logging calls added to all controller methods, and it ended up inefficient and almost ugly.
That's how I came to realize that this stuff should be rebuilt - as a package decoupled from business code, efficient, easily configurable and covering most of the needs of Web Api runtime diagnostics. The result is the Vita Web project which I'm happy to share with you folks.
May 10, 2014 at 8:38 PM
Edited May 30, 2014 at 5:54 PM
What is missing and what's ahead
One obvious thing missing is Log viewer app, to have a convenient admin access to server logs, with nice formatting and automatic links from error log to web call log. There's a primitive error viewer page with page builder (in Vita.Modules.ErrorLog module), but this is a temp substitute, not forever. LogViewer and more broadly Admin app with bunch of viewers and management facilities is something in the plans.
Currently, logging is not integrated with login facilities and user session handling - this is coming too, most likely in the near future. For this I need to finish refactoring and extending login module, which is coming very soon. One new log that probably will appear is IncidentLog - for tracking events that are not errors but deserve some attention. Like failed login event - too many of these in a row may signal that a password cracking attack is on the way.
Validation exception on the server side is handled in a primitive way - the service returns BadRequest with validation error in the body. Advanced scenarios would require ability to return a stucture (json list) with multiple validation error objects. For example, let's say you have a page with multiple controls; user edits the values and clicks 'Submit'. The javascript behind the button submits the data to the RESTful service. If validation on the server fails with multiple errors, it should return all errors, each with related information (related control), so that client-side javascript may properly display error indicators/messages next to the corresponding controls. This functionality will be coming, it is in the works.