Enhancing log4net exception logging

Using a library like log4net is surely helpful in your day to day app development. One of the most important cases where an entry should be logged is an application exception occurring on the production environment. It’s quite common to use Windows’ event logs as a storage for log entries and log4net has a special appender which is used in this cases called simply EventLogAppender. All it does by default is appending an entry to the Application event log using a parametrized event source name. It does not set an event id or a category of the entry, disabling a simple querying of entries by this param. There are imperative ways of adding one, like by adding an element EventID or Category to a dictionary log4net.ThreadContext.Properties. This makes you either wrap each call to log4net with a proxy (it’s useful and may be used in your project) or pollute your code with plenty of a logging logic. Can it be done in another way?

Filter to the rescue
It’s not quite hard to provide a better, separated way of enhancing your log entries on the information based on the exception object being thrown. One of them is using a filter, which has an ability to access an exception by a LoggingEvent instance. A simple code of doing it can be found in the following gist.

As you can see, the consts of EventID and Category are stored in the filter’s implementation as the original EventLogAppender uses inline consts to check them. Once their added they will be used by the mentioned EventLogAppender to mark the given entries with EventId and Category. The logic of determining them is up to you. You can hash the exception stacktrace, use an exception’s source property or something else. At the very end remember to add this filter to your appender. Happy logging! ;-)

Overvalidated design

Imagine, that you’re requested to allow adding additional validation in an ASP MVC application to properties of some models. The set of properties’ types is given and contains following types: string, int, DateTime, a reference to a glossary entity. The business (why?) scenario is irrelevant and will be not exposed here.
To allow MVC work nicely there are multiple ways to resolve this case. The following ways may be used:

  • a custom ModelValidatorProvider implementation can be provided, which takes the validation information saved in some storage and applies to
  • an extension to TypeDescriptor facilities, to add attributes to the specified properties

But how to store this information, being given a meta description (types and their properties already mapped to entities in a database). The first take was to provide an abstract class Validator and try to subclass it with a fully descriptive design, allowing saving any type of parameter, with any kind of operator. You can imagine how many enums, objects (not so strongly typed API) it created.

The “what for?” question arose. Being given a set of types and possibilities of their validation why not to provide validators tightly coupled to those types? If the set of validated types is frozen, the switches can be easily replaced with visitors (very stable hierarchy), which can easily transform the given data into sth which may be used by MVC.

Validators data new design

Having your information about validators correlated with types, which should not be changed in a while, allows you for easier editing and storing (no more operators, objectly typed properties). The transformed values can be easily applied via ModelValidator or added as attributes to the TypeDescriptor of the given model. This approach creates a simple pipeline with a possibility of getting the procession result in any moment and inject it in the framework (ASP MVC) in a preferable way.

A CRUD action provider

As it was described in the previous entry, the idea of the action providers is to allow to gather cross-cutting concerns into more generic (not in the C# terms, but functionalities/features) bag than a derivation from a generic controller. To provide a working example, a standard CRUD operations can be taken into the consideration. Let’s take a look into another gist.
I do hate static code, but for sake of a simplicity all the CRUD operations were moved to a static class, CrudActions. All of them are pretty simple, as they use an entity model binder introduced in the former blog entries. For instance, when an entity edit result is posted to the server, a model binder will take care of updating the entity, so the entity being passed to the [HttpPost]Edit will be already altered with the changes made by a user.
The very second step was discovering all of the CrudActions. It is made by a DetachedActionProvider which caches information in a ReadWriteCache taken from the MVC internals. To close the open generic of CrudActions, an entity type with an id’s type is needed. The entity type information is retrieved from a IEntityController, which is a simple markup convention (you can come up with a name convention, or delegate it somewhere else), for attaching to a controller a handled entity type. The id metadata are gathered from the NHibernate’s ISessionFactory. Once the data are retrieved, the CrudActions generic class definition can be turned into a closed generic and the specific method can be found.
Wait a second… how do we transform a MethodInfo into an ActionDescriptor? First, the method infos are wrapped with an ActionInfo instance (it caches attributes as well as the method info itself). Next, the ActionInfos, those who applies (HttpGet, HttpPost, etc.), are passed to the ReflectedMvc to create a ReflectedActionDescriptor.
At the end I left some bitterness about MVC internalization policy. I must admit, that I don’t understand internalizing types or constructors or any members which could be helpful for future app development. That case applies to the ReflectedActionDescriptor ctor, which (the public one) throws an exception if the method passed to it is a static method. The other, non-checking one, is of course internalized. I’m asking: why? The internalization should be used as a last resort, no as a ‘hide it, because I cannot predict if someone doesn’t want to crush MVC in his project’ rule.

Hope you like the action provider extension point and will use it for cross-cutting, ‘I can compose, not only derive from a generic class’ actions in your controllers.

How to guide users of your API

After winter holidays it was time to get back to the reality and to make up for the pleanty of unread posts in my reader. One of the read posts was Christopher Bennage’s entry about RavenDB API. The main problem with API was that it allows calling every Linq extension method on the Raven session. Even, the unwanted one – ToList. Christoper’s proposal is to provide an obsolete ToList method, which accepts the Raven query interface, and by being obsolete informs about the best way of getting a list of objects.

Simple, nice, powerful.

You don’t mess with Unity’s policies

Recently I ran into a problem. Quite well designed system degraded in terms of performance after a few commits. The whole architecture is wired with an infrastructure library written with unity container as a base for dependency injection. One of its features is a simple adding proxies, for instance adding some information to an exception’s data in case of throwing one. The interceptor doing it is quite simple:

public class ExceptionDataAppendingInterceptor : IInterceptor
{
	public void Intercept(IInvocation invocation)
	{
		try
		{
			invocation.Proceed();
		}
		catch (Exception ex)
		{
			ex.AppendMethodCallData(
			    invocation.Method, invocation.Arguments);
			throw;
		}
	}
}

The exension method appending data is a bit more complex but does not add any value to the post.

Having in mind that exception can be thrown at various points of an application and having it run for the very first time in the test environment, I configured unity to set proxy to the majority of created objects, which are resolved as interfaces (proxifing their interfaces).
When I run a profiled, it showed a major overhead created by one strategy, being responsible for wrapping a created object with use of DynamicProxy2. What the profiler shown was plenty of calls to IEnumerable extensions method. The strategy called one policy which before fixing looked like this:

public class InterceptorSelectorPolicy : IBuilderPolicy
{
	private readonly IDictionary<Type, List<Func<IBuilderContext, IInterceptor>>> 
		_activators;
	private static readonly ProxyGenerator ProxyGenerator = new ProxyGenerator();

	public InterceptorSelectorPolicy(
		IDictionary<Type, List<Func<IBuilderContext, IInterceptor>>> activators)
	{
		_activators = activators;
	}

	/// <summary>
	/// Determines whether the specified context is applicable for proxy generation.
	/// </summary>
	public bool IsApplicable(IBuilderContext context)
	{
		return _activators.ContainsKey(BuildKey.GetType(context.OriginalBuildKey));
	}

	/// <summary>
	/// Creates the proxy using <see cref="IBuilderContext.Existing"/> as target
	/// and <see cref="IBuilderContext.OriginalBuildKey"/> as proxied interface type.
	/// </summary>
	public object CreateProxy(IBuilderContext context)
	{
		var typeToProxy = BuildKey.GetType(context.OriginalBuildKey);

		return ProxyGenerator.CreateInterfaceProxyWithTarget(
			typeToProxy,
			context.Existing,
			_activators[typeToProxy]
			.Select(a => a(context))
			.ToArray());
	}
}

It’s worth to mentioned that it was called every time an object was created… After refactorization the code lost all the enumerable _create_state_machine_for_my_iterator_ stuff and was changed to:

public class InterceptorSelectorPolicy : IBuilderPolicy
{
	private readonly Type _typeToProxy;
	private readonly Func<IBuilderContext, IInterceptor>[] _activators;
	private static readonly ProxyGenerator ProxyGenerator = new ProxyGenerator();

	public InterceptorSelectorPolicy(Type typeToProxy, 
		Func<IBuilderContext, IInterceptor>[] activators)
	{
		_typeToProxy = typeToProxy;
		_activators = activators;
	}

	/// <summary>
	/// Gets a value indicating whether this proxified should be applied.
	/// </summary>
	/// <value>
	///     <c>True</c> if this instance is applicable; otherwise, <c>false</c>.
	/// </value>
	public bool IsApplicable
	{
		get { return _activators != null && _activators.Length > 0; }
	}

	/// <summary>
	/// Creates the proxy using <see cref="IBuilderContext.Existing"/> as target
	/// and <see cref="IBuilderContext.OriginalBuildKey"/> as proxied interface type.
	/// </summary>
	/// <param name="context">The context.</param>
	/// <returns>Returns created proxy.</returns>
	public object CreateProxy(IBuilderContext context)
	{
		return ProxyGenerator.CreateInterfaceProxyWithTarget(
			_typeToProxy,
			context.Existing,
			CreateInterceptors(context));
	}

	private IInterceptor[] CreateInterceptors(IBuilderContext context)
	{
		var result = new IInterceptor[_activators.Length];
		for (var i = 0; i < _activators.Length; i++)
		{
			result[i] = _activators[i](context);
		}
		return result;
	}
}

No dictionary look ups, no iterators, no needed overhead. The whole idea was simplified and now, for an object having no need of proxifing it is reduced to a simple, nolock _is_null_ array check called by a post build strategy. You don’t mess with Unity’s policies unless you have a nice stress test written.

NHibernating with interfaces as entities, pt. 2

The solution to the question, what can go wrong with NHibernate, when you use interfaces as your entities mapped with NH is… naming.

When you try to save a transient object, to make it persistent with NH, you call ISession.Save(object) method. If you drilled down its implementation you’d see that it fires NH’s event SaveOrUpdateEvent which finally, after calling the default event handler for this event, would try to get the persister of the entity being saved. What for? Because you’ve got to know how you are trying to make persistent and later, saved in a db.

Let’s take a look at the implementation provided with a SessionImpl.GetEntityPersister method. At the very first lines of code, the method calls another session’s method called GuessEntityName. Guessing method firstly delegates the question to the interceptor, and if one was kind enough to help it to deal with it, it returns the result of the interceptor’s call. Otherwise… GetType of the entity method is called! If the result of resolving entity’s interface from container was wrapped with a proxy, some proxy type will be returned (in DynamicProxy it will be nicely placed in a dynamic assebly with a cute namespace) and because it is not what was mapped, an error will occur!

The only solution is to traverse all interfaces implemented by the object and find the one you’ve written in your mappings in the interceptor method. You can do it simply with the code presented below, initializing the finder with all interfaces of all your entities. Remember to do not cross trees in a forest of your interface-entity derivations:P

/// <summary>
/// The interface finder allows you to find the deepest interface from a specified set of interfaces.
/// </summary>
/// <remarks>
/// The interfaces inheritance graph should be a forest.
/// </remarks>
public class InterfaceFinder : IDisposable
{
	private readonly List<Type> _interfaces;
	private readonly Dictionary<Type, int> _interfaceToLevel;
	private readonly Dictionary<Type, Type> _cacheObjectTypeToInterface;
	private readonly ReaderWriterLockSlim _rwl;

	public InterfaceFinder(IEnumerable<Type> interfaces)
	{
		if (!interfaces.Any())
		{
			throw new ArgumentException("No interfaces passed", "interfaces");
		}

		_interfaces = interfaces.ToList();
		_interfaceToLevel = new Dictionary<Type, int>();
		_cacheObjectTypeToInterface = new Dictionary<Type, Type>();

		// prepare dictionary counting ancestors
		foreach (var i in interfaces)
		{
			if (!i.IsInterface)
			{
				throw new ArgumentException(string.Format("The type {0} is not an interface", i.FullName));
			}

			var ancestorCount = i.GetInterfaces().Count(t => interfaces.Contains(t));
			_interfaceToLevel[i] = ancestorCount;
		}

		// create only when fully initialized
		_rwl = new ReaderWriterLockSlim();
	}

	/// <summary>
	/// Gets the depest interface from inheritance trees retrieved from
	/// the constructor parameter.
	/// </summary>
	/// <param name="o">The object to be searched for interfaces.</param>
	/// <returns>The deepest interface of a hierachy found in the object interfaces.</returns>
	public Type GetDeepestInterface(object o)
	{
		o.ThrowIfNull("o");

		var type = o.GetType();

		// enter read lock, try found, multiple threads can enter
		_rwl.EnterReadLock();
		try
		{
			Type result;
			if (_cacheObjectTypeToInterface.TryGetValue(type, out result))
			{
				return result;
			}
		}
		finally
		{
			_rwl.ExitReadLock();
		}

		// write lock, cause no entry found, one thread can enter
		_rwl.EnterWriteLock();
		try
		{
			Type result;
			if (_cacheObjectTypeToInterface.TryGetValue(type, out result))
			{
				return result;
			}

			result = GetDeepestInterface(type);
			_cacheObjectTypeToInterface[type] = result;
			return result;
		}
		finally
		{
			_rwl.ExitWriteLock();
		}
	}

	private Type GetDeepestInterface(Type objType)
	{
		var interfaces = objType.GetInterfaces().Intersect(_interfaces);

		var levels = interfaces.Select(t => _interfaceToLevel[t]).ToArray();
		var countDistinct = levels.Distinct().Count();

		if (countDistinct != levels.Length)
		{
			throw new InvalidOperationException(
				"The type of passed object implements to many interfaces, " +
			"disallowing to find one path in derivation tree. The found implemented interfaces are: " +
			string.Join(", ", interfaces.Select(i => i.FullName).ToArray()));
		}

		// find the interface with the biggest depth
		return interfaces.OrderByDescending(t => _interfaceToLevel[t]).First();
	}

	public void Dispose()
	{
		_rwl.Dispose();
	}
}

Tests not included :P

NHibernating with interfaces as entities, pt. 1

No catchy title this time:P
Have you ever considered using interfaces as entities in your application with NH as ORM? If not, and you never considered this option I can share a few thoughts about it with you.

Proxifing an interface is easier than proxifing a class, especially when using a tool like DynamicProxy which as far as I know still does not has this ability (yep, I’ve read about it on Kozmic’s blog). Why on earth proxify each entity you may ask? During the last project I was involved in, my colleague wanted to ensure, that setting properties and calling methods of one entity can be done only in explicitly set up scopes (explicit security). It’s quite easy when you can intercept all the setters and other, non-property method calls. All you’ve got to do is during instantiation of an entity wrap it with a certain proxy. What about instantiating entities’ implementations? There should be some, because it very unpleasant to have your entities only data oriented with no methods at all. This can be easily done with your implementation of NH’s IInterceptor. There is an interceptor method Instantiate(string entityName, EntityMode entityMode, object id); which, with help of your favorite container, can be turned into a entity factory. The code would look like this:

public override object Instantiate(string clazz, EntityMode entityMode, object id)
{
	if (entityMode == EntityMode.Poco)
	{
		var metadata = _sessionFactory.GetAllClassMetadata()[clazz];
		var type = metadata.GetMappedClass(entityMode);

		if (type != null)
		{
			var instance = _unityContainer.Resolve(type);
			var classMetadata = _sessionFactory.GetClassMetadata(clazz);

			classMetadata.SetIdentifier(instance, id, entityMode);

			return instance;
		}
	}

	return null;
}

The session can easily create the entity to hydrate it, we can be given our ISomeEntity with Load, Get, List. What about creating your entity for the first time? It can be also achieved providing an interface of IEntityFactory implemented with usage of the very same container used in the interceptor.
So far so good. But is there a catch? Yes there is and it’ll be revealed soon :)