Http 400 Error – Bad Request

Today I spend the entire day dealing with “Http 400 Error – (Bad Request)” which I was getting from one of our web services (ESB service on WAPP6). I rebuilt the involved client and backend services but it didn’t fix the issue. The weird thing was that I would get this error only for a number of requests and for the rest of them the application worked. The backend service used to run on two servers but we had taken out one of them from the load balancer for a couple of months, so at that moment we only had one instance of the service and the other one had been deleted.
After spending half a day looking into this issue we realized that it must have been an issue in our load balancer that would send some of the requests to the deactivated server (even though we had instructed our load balancer not to send any requests to it). The issue looked fixed once we reconfigured the load balancer, but after a couple of minutes it showed up again. Finally it turned out that the issue was caused by a DNS misconfiguration that would send the requests to the deactivated server. We changed the DNS config and it fixed the issue. The following log files and command helped to identify the issue:
C:\WINDOWS\system32\LogFiles\HTTPERR
C:\WINDOWS\system32\LogFiles\W3SVC1

nslookup west.esb.mathletics.com

Logging Best Practices

In this article I will cover the best practices of logging in terms of the following concerns, regardless of what logging framework we use:
1- What to log
2- How to choose logging levels
3- Where to log

What to log

First of all logging is not a constant forward process. You don’t have to log all you need and then stop touching it. It can be an ongoing process and you can refactor your logging codes as your needs. Although we don’t have to write every possible event of our application upfront just in case we might have need it in future, there are some minimum events that we should log at first place.
All errors and critical conditions should be logged. It doesn’t mean that we should log an error in every Catch clause, because whether or not the caught exception is an error to log, depends on what that exception is and how you are going to handle it. For example your Catch clause might have caught a predicted “Access Denied” exception and have made the appropriate decision. This is not considered as an error but a lower log level like Debug never harms. Any unusual circumstances should be logged even if they don’t effect the application. Consider that the last example is not considered as an unusual circumstance either. It is also a good idea to log the starting point and end point of every process. Ideally if we have singly responsible methods, that would be logging at the beginning and end of each method. We don’t have to log every single parameter of each method but we can log some critical information such as endpoint URLs, connection strings or IDs. We can add more debugging logs later on if we need to. Never worry about too much logs, because almost all of the logging frameworks allow you to disable your logs partially. You can filter them based on the type for which you have logged or the level of your logs. So it is important to name your loggers after their surrounding types or at least give them a meaningful name, as the logger names will later be used for grouping and filtering the logs. It is also crucial to choose appropriate logging levels.

How to choose logging levels

I will never use Info logging level for Debug purposes.
Although logging frameworks allow us to have as many custom logging levels as we need, there are usually several default logging levels that are mostly used:
Fatal: Usually the highest level. Used when a problem stops the application’s functionality. This kind of errors usually happen because of unexpected circumstances for which no alternative solutions are provided. For example, no disk space, network disconnection or any unexpected circumstances which stops the application.
Error: This level is used when an error occurs but it is handled and it doesn’t interrupt the application. It may cause some minor problems or may lead to some consequences in the future. For example a connection to the master database is refused and we redirected the request to the slave to handle the issue.
Warn: For logging unusual circumstances that need consideration or they may lead to future problems. Low disk space is an example which may needs a warning level log.
Info: We use this logging level for monitoring the application’s process. It should be so that when someone reads the logs they can realize what is going on in the application. They shouldn’t contain debugging data or repeated information. So It’s not a good idea to use Info logging level in long loops.
Debug: This is the lowest logging level and it usually contains too much information that we often tend to filter this level out and use it only while debugging the application. It can contain any details that normally we don’t need to see in the logs.

Info or Debug

It is sometimes confusing whether to use Info or Debug. One of the common mistakes is that some developers use debug level for logging of dependencies. For example when a business object is using a data access object which needs to log some database operations, it may look like the data access object should use the debug level as it is serving a lower level functionality. However, when we choose the logging level for a component, we should consider that component in isolation. Any class can be a dependency for a higher level type and at the same time it may depend on other lower level components. When we read the logs we can filter only those components that we need to monitor or debug. So the lower level types should also have their own levels of Info and Debug. This is easier to handle when the application concerns are separated into individual classes. Otherwise you will have to consider a lower priority for some of the multiple concerns which are being addressed in a single class and choose Debug level for them to distinguish them from the main concerns of the same class.

Where to log

The easiest way to log is logging in between your code. But ideally we should consider that each object should have its own concern and logging is yet another concern. So we should separate it and put it somewhere else. Since logging is not limited to a specific layer of the application, it is a cross-cutting concern and two of the best practices to address such concerns are the Decorator design pattern and Aspect Oriented Programming (AOP). Both approach allow you to put your logging logic in separate classes and attach them to the type which is going to be logged. They allow you to log prior to, after, in case of success or in case of failure of a method. One may argue what if they need to log in the middle of a method. The answer is if each method is dealing with a single responsibility you won’t need that. The following code needs to be refactored so we won’t need to log in the middle of the Transfer method.

void Transfer(string source, string dest, Money amount)
{
    log.Info("Transferring...");
    log.Info("Debiting {0}...", source);
    ... // Debiting implementation
    log.Info("{0} debited.", source);
    log.Info("Crediting {0}...", dest);
    ... // Creddiing implementation
    log.Info("{0} debited.", dest);
    log.Info("Transfer finished.");
}

The followoing shows how to refactor the above code:

void Transfer(Account source, Account dest, Money amount)
{
    log.Info("Transferring...");
    source.Debit(amount);
    dest.Credit(amount);
    log.Info("Transfer finished.");
}

The Debit and Credit implementation should be moved to the Account object.

public class Account
{
    public string Number {get;set;}

    public void Debit(Money amount)
    {
        log.Info("Debiting {0}...", this.Number);
        ... // Debiting implementation
        log.Info("{0} debited.",  this.Number);
    }

    public void Credit(Money amount)
    {
        log.Info("Crediting {0}...",  this.Number);
        ... // Creddiing implementation
        log.Info("{0} debited.",  this.Number);
    }
}

Another moral of the above example is that the calling code should not take care of logging for the called method. Each method should log their own responsibilities only.

Interception with Ninject

There are cases where we need to do some operations before or after calling a single method or a number of methods. For example, we may need to log something before and after invoking all the methods in a component. Interception allows us to wrap the injecting dependency in a proxy object which can perform such operations before, after, around or instead of each method invocation. This proxy object can then be injected instead of the wrapped service. Ninject Interception extension creates such proxy wrappers on the fly and allows us to intercept invocations of the wrapped service members. The following diagram shows how a service will be replaced with an intercepted one during the interception process.

6207_05_01

Interception is one of the best practices for implementing Cross Cutting Concerns such as logging, caching, exception handling, or transaction processing.

Setup Interception

Ninject Interception extension generates proxy instances based on the DynamicProxy implemented by LinFu or Castle. We can choose which implementation to use when referencing interception extension. Using NuGet either install Ninject.Extensions.Interception.DynamicProxy or Ninject.Extensions.Interception.Linfu. NuGet will also automatically install Ninject, Ninject.Extensions.Interception and Castle.Core or LinFu.DynamicProxy depending on the selected DynamicProxy implementation. In this section, we will use Castle DynamicProxy. We can also download and reference the binary files of these libraries manually. Finally we need to add the following using statements to the code:

using Ninject.Extensions.Interception;
using Ninject.Extensions.Interception.Infrastructure.Language;

Member Interception

Once we have setup our project for Interception extension, some extension methods will be available via the kernel which can be used for interception. We can use these methods to intercept a method or property. Here are a few of them:

InterceptReplace<T> (Expression<Action<T>>, Action<IInvocation>)
InterceptAround<T> (Expression<Action<T>>, Action<IInvocation>, Action<IInvocation>)
InterceptBefore<T> (Expression<Action<T>>, Action<IInvocation>)
InterceptAfter<T> (Expression<Action<T>>, Action<IInvocation>)

The following example shows us how to use a method interception to log around the GetAllCustomers() method of the CustomerService class:

Kernel.InterceptAround<CustomerService>(
    s=>s.GetAllCustomers(),
    invocation =>logger.Info("Retrieving all customers..."),
    invocation =>logger.Debug("Customers retrieved"));

In the preceding example, the type parameter indicates the service we are going to intercept (that is, CustomerService). The first parameter is a delegate which indicates the method to intercept (for example, GetAllCustomers). For the InterceptAround method, the second and third parameters are two delegates which will be executed before and after invoking the intercepted method respectively.

The invocation parameter whose type is IInvocation, provides useful information about the method invocation context. For example, we can get or change the returned value. In the following example, we will log the number of retrieved customers using the InterceptAfter method:

Kernel.InterceptAfter<CustomerService>(s=>s.GetAllCustomers(),
    invocation =>logger.DebugFormat("{0} customers retrieved", (IEnumerable<Customer>) invocation.ReturnValue).Count()));

Since the type of ReturnedValue is object, we need to cast it to reach the Count() method. In the following example, we will implement caching for the GetAll() method of the customers repository:

Kernel.InterceptReplace<SqlCustomerRepository>(
r => r.GetAll(),
invocation =>
{
    const string cacheKey = "customers";
    if (HttpRuntime.Cache[cacheKey] == null)
    {
        invocation.Proceed();
        if (invocation.ReturnValue != null)
            HttpRuntime.Cache[cacheKey] = invocation.ReturnValue;
    }
    else
        invocation.ReturnValue = HttpRuntime.Cache[cacheKey];
});

In this example, we used the InterceptReplace method which can totally replace the functionality of the intercepted method. We used HttpRuntime.Cache for caching the list of Customer objects, which the GetAll() method returns. If the Cache object is empty, we need to call GetAll(), which is the intercepted method and then put the returned value in the cache. In order to call the intercepted method via the interception method (InterceptReplace), we should call the Proceed() method of the invocation object. Then we can get its returned value which is the list of Customer objects from the ReturnValue property of the invocation. If the Cache object is not empty, we just need to set the ReturnValue property to the cached Customer list. In this way, the GetAll() method will not be called.

The important thing to keep in mind is that the type argument provided for interception methods cannot be the type of the abstracted service. It should be the concrete implementation type. That is why we have provided SqlCustomerRepository rather than ICustomerRepository as the type argument for the InterceptReplace method, so the following code wouldn’t work:

Kernel.InterceptReplace<ICustomerRepository>(
r => r.GetAll(), invocation =>{  ...  });

That is because interception creates a proxy wrapper around the resolved object rather than creating a new implementation of the abstracted service.

You may have noticed that all of the InterceptXxx methods require a type argument. This obliges the application to have a reference to the dependency library which is usually not desirable. We should be able to refer to types using their names so that we can dynamically load dependency assemblies at runtime. In order to do so, we can use the AddMethodInterceptor method. Here is the implementation of the preceding example using the AddMethodInterceptor method:

var repositoryType = Type.GetType(
"Northwind.SqlDataAccess.SqlCustomerRepository, Northwind.SqlDataAccess");
Kernel.AddMethodInterceptor(repositoryType.GetMethod("GetAll"),
invocation => {    ...   });

Type Interception

While method interception targets a particular method or property of a given type, type Interception is more generalized and applies to a type or a group of types, and intercepts all of the methods and properties in a single point. In order to create an interceptor, we need to implement the IInterceptor interface. This interface has only one method, which is as follows:

void Intercept( IInvocation invocation );

In the following example, we will implement an exception handling interceptor which can catch the exceptions and hand them over to an exception handler service. It is the same as putting try-catch in all of the methods of the intercepted type:

public class ExceptionInterceptor : IInterceptor
{
    private IExceptionHandlerService exceptionHandlerService;
    public ExceptionInterceptor(IExceptionHandlerService handlerService)
    {
        this.exceptionHandlerService = handlerService;
    }

    public void Intercept(IInvocation invocation)
    {
        try
        {
            invocation.Proceed();
        }
        catch (Exception exception)
        {
            exceptionHandlerService.HandleException(exception);
        }
    }
}

The following code shows how to add the ExceptionInterceptor to our convention so that it applies to all the classes of our application:

Kernel.Bind(x => x.FromAssembliesMatching("Northwind.*")
                        .SelectAllClasses()
                        .BindAllInterfaces()
                        .Configure(b =>
                            b.Intercept()
                               .With<ExceptionInterceptor>()
                        ));

The Intercept() method is added to the configuration section of our convention and accepts the type of the desired interceptor as its type parameter. It can then activate the provided type to create and apply the interceptor object.

If we need to intercept only a certain type in a convention rule, we can use the ConfigureFor method:

Kernel.Bind(x => x.FromAssembliesMatching("Northwind.*")
                        .SelectAllClasses()
                        .BindAllInterfaces()
                        .ConfigureFor<ICustomerRepository>
         (b => b.Intercept()
                            	.With<ExceptionInterceptor>()
                        ));

If we already have an instance of our interceptor, we can use the following syntax:

var exceptionInterceptor  = Kernel.Get<ExceptionInterceptor>();
Kernel.Bind(x => x.FromAssembliesMatching("Northwind.*")
                        .SelectAllClasses()
                        .BindAllInterfaces()
                        .Configure(b =>
                            b.Intercept()
                            	 .With(exceptionInterceptor )
                        ));

The preceding example showed how to intercept types projected by a convention. It is also possible to intercept the kernel itself. The following example applies ExceptionInterceptor to all of the services resolved by the kernel, no matter how they are registered:

kernel.Intercept(context => true)
  .With<ExceptionInterceptor>();

The Intercept method accepts a predicate which is given an instance of the current activation context (IContext). This predicate indicates what services to choose for interception. In this example, we always return true, which means we intend to intercept all services. We can define any contextual condition by this predicate based on the activation context. Refer to the Contextual binding section in Chapter3 for refreshing how to define contextual conditions.

There is also a built-in interceptor class named ActionInterceptor, which can be used as a generic interceptor in case our interception logic is as simple as a single method:

Kernel
.Intercept()
.With(new ActionInterceptor (invocation =>
         log.Debug(invocation.Request.Method.Name)));

The Interception extension also contains an abstract SimpleInterceptor class, which can be extended, to create interceptors with a pre/post interception logic, and an AutoNotifyPropertyChangedInterceptor class which is designed specifically for WPF ViewModels and automates notification of property changes.

Multiple Interceptors

We already studied how to implement exception handling concern using interception. But what if we need to add more interceptors to a type? In real life scenarios we usually have to implement a variety of cross-cutting concerns on each type. Multiple interception allows us to meet this requirement. The following example shows how to address both logging and exception handling concerns using two interceptors:

kernel.Intercept(context => true).With<ExceptionInterceptor>();
kernel.Intercept(context => true).With<LoggerInterceptor>();

Alternatively, we can apply them to a convention similar to this:

Kernel.Bind(x => x.FromAssembliesMatching("Northwind.*")
            .SelectAllClasses()
            .BindAllInterfaces()
            .Configure(b =>
                            {
                                b.Intercept()
                                 .With<ExceptionInterceptor>();

                                b.Intercept()
                                 .With<LoggerInterceptor>();
                            }
                        ));

We can also register multiple interceptors on a single Binding in the same way as follows:

var binding = Bind<IService>().To<MyService>();
binding.Intercept().With<ExceptionInterceptor>();
binding.Intercept().With<LoggerInterceptor>();

When we register an interceptor for a service type, Ninject no longer resolves the service by activating the service itself. Instead, Ninject returns a proxy object which wraps an instance of the service. When we call a method on the resolved object, we are actually calling the proxy implementation of that method, rather than the actual service method. The following diagram demonstrates that the proxy method invokes the Intercept method on the first registered interceptor:
6207_05_02

If the Proceed method is called within the Intercept method, the proxy class advances to the next interceptor and executes its Intercept method. Calling the Proceed method in the last interceptor, leads to calling the actual service method. Once the actual service method is called, the control returns to the last Intercept method along with the value returned by the service method. Here is where the interceptor can perform post-invocation operations (for example, modifying the returned value). The control then returns to the previous interceptors one by one, until it reaches the proxy method which was initially called. The following diagram shows this sequence:
6207_05_03

When we register multiple interceptors, the order in which they intercept can be indicated using the InOrder method as follows:

Kernel.Bind(x => x.FromAssembliesMatching("Northwind.*")
            .SelectAllClasses()
            .BindAllInterfaces()
            .Configure(b =>
                            {
                                b.Intercept()
                                .With<ExceptionInterceptor>()
                                .InOrder(1) ;

                                b.Intercept()
                                .With<LoggerInterceptor>()
                                .InOrder(2) ;
                            }
                        ));

The lower the value of the order, the earlier the interceptor executes. So, in the preceding example, ExceptionInterceptor executes before LoggerInterceptor.

Intercept Attribute

Another way of registering an interceptor for a type or method is by using attributes. In order to create an attribute interceptor, we just need to derive from the InterceptAttribute class and override its CreateInterceptor method. In the following example, we create an attribute named InterceptExceptionsAttribute for intercepting exceptions:

public class InterceptExceptionsAttribute : InterceptAttribute
{
    public override IInterceptor CreateInterceptor(IProxyRequest request)
    {
        return request.Kernel.Get<ExceptionInterceptor>();
    }
}

We can then apply this attribute to a method or a type as follows:

[InterceptExceptions]
public class Sample
{    ...    }
1
We can also apply both attributes to the same type as shown in the following code:
1
[InterceptExceptions, Log]
public class Sample
{    ...   }

We can apply the interceptor attributes also to methods (remember that in either way, the method should be virtual or it will not be intercepted) as follows:

[InterceptExceptions]
public class Sample
{
    [Log]
    public virtual void DoSomething()
    {    ...    }
    ...
}

In the preceding example, all of the virtual methods within the Sample class will be intercepted by ExceptionInterceptor. The DoSomething method is also intercepted by LoggerInterceptor.
We can also specify the order of interceptors, by setting the Order property of the applied attribute as follows:

[InterceptExceptions(Order = 2)]
public class Sample
{
    [Log(Order = 1)]
    public virtual void DoSomething()
    {    ...   }
}

In the preceding example, the DoSomething method will be intercepted first by LoggerInterceptor and then by ExceptionInterceptor.
In case if we have methods which we don't want to be intercepted, we can exclude them using the [DoNotIntercept] attribute as follows:

[InterceptExceptions]
public class Sample
{
    [Log]
    public virtual void DoSomething()
    {     ...    }

    [DoNotIntercept]
    public virtual void DoSomethingElse()
    {     ...    }
}

In the preceding example, although the [InterceptExceptions] attribute is applied to the type, it doesn't intercept the DoSomethingElse method.


The above article was part of the chapter 5 of my book, Mastering Ninject for Dependency Injection, [PACKT] publishing, 2013.

Running Existing Code Asynchronously

Sometimes when you are writing a piece of code, it doesn’t look necessary to be written as an asynchronous code. However, after a while we may need to make it asynchronous. The following code sample shows how to implement such scenarios using the Decorator design pattern and Dependency Injection, such that we don’t need to touch the client code to make it asynchronous.

Here is the interface for a Worker service which can be implemented either synchronously or asynchronously:

   interface IWorker
    {
        void DoWork(object data);
    }

Suppose that the following code is our client which is calling the DoWork method of IWorker in its Run method.

    class Client
    {
        private readonly IWorker worker;

        public Client(IWorker worker)
        {
            this.worker = worker;
        }

        public void Run()
        {
            for (int i = 1; i <= 5; i++)
            {
                worker.DoWork(i);
            }

            Console.WriteLine("End.");
            Console.ReadLine();
        }
    }

The DoWork method is called sequentially before the word “End.” gets printed on the screen. So in a synchronous implementation of IWorker the output would be something like this:
Sync Output

Here is the synchronous implementation of IWorker:

    class SyncWorker : IWorker
    {
        public void DoWork(object taskNumber)
        {
            Thread.Sleep(1000);
            Console.WriteLine("Task {0} finished.", taskNumber);
        }
    }

Now if we need to make the Worker class run asynchronously, we would just need to create a decorator for the existing implementation:

    class AsyncWorker : IWorker
    {
        private readonly IWorker innerWorker;

        public AsyncWorker(IWorker innerWorker)
        {
            this.innerWorker = innerWorker;
        }

        public void DoWork(object data)
        {
            ThreadPool.QueueUserWorkItem(o => innerWorker.DoWork(o), data);
        }
    }

In order to make our code run using the new implementation of IWorker, we just need to instruct our IoC container to do so. In this example we are using Ninject as our IoC container and the service bindings are included in a Ninject module named WorkerServiceRegistry.

        static void Main(string[] args)
        {
            using (var kernel = new StandardKernel())
            {
                kernel.Load(new WorkerServiceRegistry(false));
                var client = kernel.Get<Client>();
                client.Run();
            }

        }

As the following code shows, we can even tell the WorkerServiceRegistry module whether we need a synchronous or an asynchronous implementation of IWorker:

    class WorkerServiceRegistry : NinjectModule
    {
        private readonly bool registerAsAsync;

        public WorkerServiceRegistry(bool registerAsAsync)
        {
            this.registerAsAsync = registerAsAsync;
        }

        public override void Load()
        {
            if (registerAsAsync)
            {
                Bind<IWorker>().To<AsyncWorker>();
                Bind<IWorker>().To<SyncWorker>().WhenInjectedInto<IWorker>();
            }
            else
            {
                Bind<IWorker>().To<SyncWorker>();
            }
        }
    }

In this example we have decoupled our client code from our concrete worker and also separated the concern of running the code asynchronously, that’s why we could easily intercept the sync worker and substitute it with an async version of it.
This approach can also be implemented using the Interception feature of your IoC container. In that case we will no longer need our decorator class. Instead, we will have to create an interceptor. It will look like this:

    internal class AsyncInterceptor : IInterceptor
    {
        public void Intercept(IInvocation invocation)
        {
            ThreadPool.QueueUserWorkItem(o => invocation.Proceed());
        }
    }

To wire up our interceptor, we need to introduce it to our IoC container. Here is the updated version of the Load() method of our WorkerServiceRegistry class which uses the interceptor instead of the SyncWorker decorator:

        public override void Load()
        {
            if (registerAsAsync)
            {
                Bind<IWorker>().To<SyncWorker>().Intercept().With<AsyncInterceptor>();
            }
            else
            {
                Bind<IWorker>().To<SyncWorker>();
            }
        }

For more information on how to use Interception in Ninject visit this post.