Logging NHibernate Queries with Parameters

NHibernate lets you log the SQL statements it constructs using log4net. I’m not going to explain how to do it, because it is already well explained. It gives you flexibility on where you want to log: console, text file, XML file, etc. The output that you get looks something like this:

12:33:54,464 DEBUG SQL:56 -
SELECT
    count(CategoryId)
FROM
    ProductCategories
WHERE
    ProductId=@p0;
 @p0 = 65536 [Type: Int32 (0)]

Notice that the query contains parameter name, not value – values are listed on the bottom.

Sometimes, you want to run this query using a tool other than NHibernate, SQL Server Management Studio, for example. Then, you’ll have to copy the appropriate parameter values and replace it in a query. Doing it by hand is a waste of time, so I wrote a custom log4net appender, that does it for us. Here’s the source code:

public class NHAppender: ForwardingAppender
{
	protected override void Append(LoggingEvent loggingEvent)
	{
		var loggingEventData = loggingEvent.GetLoggingEventData();

		if(loggingEventData.Message.Contains("@p"))
		{
			StringBuilder messageBuilder = new StringBuilder();

			string message = loggingEventData.Message;
			var queries = Regex.Split(message, @"command\s\d+:");

			foreach (var query in queries)
				messageBuilder.Append
				(ReplaceQueryParametersWithValues(query));

			loggingEventData.Message = messageBuilder.ToString();
		}

		base.Append(new LoggingEvent(loggingEventData));
	}

	private static string ReplaceQueryParametersWithValues(string query)
	{
		return Regex.Replace(query, @"@p\d(?=[,);\s])(?!\s*=)", match =>
		{
			Regex parameterValueRegex = new Regex
			(string.Format(@".*{0}\s*=\s*(.*?)\s*[\[].*", match));
			return parameterValueRegex.Match(query).Groups[1].ToString();
		});
	}
}

What I’ve done here is derive from a ForwardingAppender, that lets you transform the output logged and forward it to another appender. The NHAppender replaces the parameter names in query (@p0, @p1 and so on) with appropriate values, taking batch commands into account (notice the usage of Regex.Split).

You can use this appender to forward fully executable SQL queries to the console like this in your configuration:

<appender name="NHAppender" type="NHibernatePlayground.Custom.NHAppender, 
	NHibernatePlayground">
	<appender-ref ref="console" />
</appender>

<root>
	<appender-ref ref="NHAppender" />
</root>

This way, you can copy the queries from console output and execute it immediately.

CodeProject