Friday, January 15, 2010

Logging SQL statements in any ADO.NET DAL with PostSharp post-compilation

You cannot overestimate the usefulness of looking at exact SQL your application is executing. Development, support, migration – all kinds of projects benefit when you can just paste exact SQL in SQL studio instead of guessing query parameters.

Usual ways of obtaining it are:

  • SQL Server profiler
  • Logging built in your DAL

Now, if you start to think about consulting or contracting scenarios, both of these options can be unavailable. Original development team could’ve chosen a DAL without adequate built-in SQL statement logging, like Spring.NET, or just a bunch of ADO.NET calls all over the place. SQL profiler is a universal tool, but it can be forbidden if application runs against a locked-down production DB. And personally I always found it a chore to set it up so it logs only your queries.

Solution that comes to mind is just to add some custom logging yourself, even without committing it to shared repository. One of the ways to do it is post-compilation (and another way is manual or automated source modification). With post-compiler you first compile your DAL, and then let a tool rewrite some parts of library to add logging statements directly to IL.

Here is how you can do it with PostSharp:

0. Download and install PostSharp from www.postsharp.org. It is an open-source tool, but  you will need to register to download it.

1. Create a logging aspect.

Aspect is a piece of code that you will declaratively apply to different method calls. In my example code will be applied to all calls to System.Data.IDCommand.ExecuteReader and friends and will log text and parameters of executing SQL command.

To do it create a class inheriting from PostSharp.Laos.OnMethodInvocationAspect. Override OnInvocation method and you get access to the current object method is being called on (e.g. SqlCommand). Log whatever you wish and continue normal execution by calling eventArgs.Proceed().

Here is the complete example of logging aspect that uses log4net framework.

   1: public class LogAdoNetAttribute : OnMethodInvocationAspect
   2: {
   3:     #region Runtime
   4:  
   5:     [NonSerialized]
   6:     private ILog _log;
   7:  
   8:     public override void RuntimeInitialize(MethodBase method)
   9:     {
  10:         _log = LogManager.GetLogger(method.DeclaringType);
  11:     }
  12:  
  13:     public override void OnInvocation(MethodInvocationEventArgs eventArgs)
  14:     {
  15:         if (_log.IsInfoEnabled)
  16:             LogCommand((IDbCommand)eventArgs.Instance);
  17:  
  18:         eventArgs.Proceed();
  19:     }
  20:  
  21:     private void LogCommand(IDbCommand command)
  22:     {
  23:         string paramString = String.Join(", ", command.Parameters.Cast<DbParameter>().Select(param => string.Format("{0}='{1}'", param.ParameterName, param.Value)).ToArray());
  24:         _log.Info(String.Format("{0} {1}", command.CommandText, paramString));
  25:     }
  26:  
  27:     #endregion
  28: }

2. Apply aspect.

As you could notice, our aspect is actually an Attribute, assembly-level MulticastAttribute to be precise. MulticastAttribute is a PostSharp concept of attribute that applies to lots of different class members with one declaration. Now I’m going to put my new LogAdoNetAttribute on assembly that contains calls to ADO.NET, and specify methods I want to intercept.

   1: [assembly: LogSqlAspects.LogAdoNetAttribute(
   2:     AttributeTargetAssemblies = "System.Data",
   3:     AttributeTargetTypes = "System.Data.*Command",
   4:     AttributeTargetMembers = "Execute*"
   5:     )]

As you see, I applied attribute to ExecuteReader, ExecuteNonQuery, ExecuteScalar methods of IDbCommand,  SqlCommand, OdbcCommand and some other classes in System.Data assembly.

3. Post-compile

When you add an attribute to assembly, you will need to reference PostSharp.Laos and PostSharp.Public libraries. If you have PostSharp installed, it will detect this and automatically launch during post-build event (that is hooked up machine-wide). PostSharp will take a compiled assembly, find all calls to ExecuteReader etc and replace them with calls to AspectsImplementationDetails_1 class that it compiles from your aspect code. You can take a look at implementation with Reflector.

That’s it!

How would I use it?

If I need to add logging to a custom DAL, I can just drop an attribute, reference 2 libraries and recompile. No need to manually modify code, and then painfully track what code should be committed and what shouldn’t.

If the code uses an open-source DAL library, like Spring.NET, I can add attribute to it, compile my custom build of Spring.NET and drop it into libs folder.

If the code uses a closed-source DAL, then I will try to find an appropriate API and intercept calls to it instead.

Hope this helps someone, at least I didn’t find complete examples on how to do it online. You can download complete source from github: http://github.com/casual/LogSqlAspects. And if you have questions or corrections, please leave a comment or ping me on twitter: http://twitter.com/casualdev/.