Intercept SQL statements containing parameter values generated by NHibernate

Question

I use a simple interceptor to intercept the sql string that nhibernate generates for loging purposes and it works fine.

public class SessionManagerSQLInterceptor : EmptyInterceptor, IInterceptor
    {
        NHibernate.SqlCommand.SqlString IInterceptor.OnPrepareStatement(NHibernate.SqlCommand.SqlString sql)
        {
            NHSessionManager.Instance.NHibernateSQL = sql.ToString();
            return sql;
        }
    }

This however captures the sql statement without the parameter values.. They are replaced by '?'

Eg: .... WHERE USER0_.USERNAME = ?

The only alternative approach i found so far is using log4nets nhibernate.sql appender which logs sql statement including parameter values but that is not serving me well..

I need to use an interceptor so that for eg. when i catch an exception i want to log the specific sql statement that caused the persistence problem including the values it contained and log it mail it etc. This speeds up debuging great deal compared to going into log files looking for the query that caused the problem..

How can i get full sql statements including parameter values that nhibernate generate on runtime?

Answer 1

Here is (roughly sketched) what I did:

1. Create a custom implementation of the IDbCommand interface, which internally delegates all to the real work to SqlCommand (assume it is called LoggingDbCommand for the purpose of discussion).

2. Create a derived class of the NHibernate class SqlClientDriver. It should look something like this:

   public class LoggingSqlClientDriver : SqlClientDriver
   {
       public override IDbCommand CreateCommand()
       {
           return new LoggingDbCommand(base.CreateCommand());
       }
   }
   

3. Register your Client Driver in the NHibernate Configuration (see NHibernate docs for details).

Mind you, I did all this for NHibernate 1.1.2 so there might be some changes required for newer versions. But I guess the idea itself will still be working.

OK, the real meat will be in your implementation of LoggingDbCommand. I will only draft you some example method implementations, but I guess you'll get the picture and can do likewise for the other Execute*() methods.:

public int ExecuteNonQuery()
{
    try
    {
        // m_command holds the inner, true, SqlCommand object.
        return m_command.ExecuteNonQuery();
    }
    catch
    {
        LogCommand();
        throw; // pass exception on!
    }
}

The guts are, of course, in the LogCommand() method, in which you have "full access" to all the details of the executed command:

• The command text (with the parameter placeholders in it like specified) through m_command.CommandText
• The parameters and their values through to the m_command.Parameters collection

What is left to do (I've done it but can't post due to contracts - lame but true, sorry) is to assemble that information into a proper SQL-string (hint: don't bother replacing the parameters in the command text, just list them underneath like NHibernate's own logger does).

Sidebar: You might want to refrain from even attempting to log if the the exception is something considered fatal (AccessViolationException, OOM, etc.) to make sure you don't make things worse by trying to log in the face of something already pretty catastrophic.

Example:

try
{
   // ... same as above ...
}
catch (Exception ex)
{
   if (!(ex is OutOfMemoryException || ex is AccessViolationException || /* others */)
     LogCommand();

   throw;  // rethrow! original exception.
}

Answer 2

It is simpler (and works for all NH versions) to do this :

public class LoggingSqlClientDriver : SqlClientDriver
{
    public override IDbCommand GenerateCommand(CommandType type, NHibernate.SqlCommand.SqlString sqlString, NHibernate.SqlTypes.SqlType[] parameterTypes)
    {
        SqlCommand command = (SqlCommand)base.GenerateCommand(type, sqlString, parameterTypes);

        LogCommand(command);

        return command;
    }}

Answer 3

Implement custom ILoggerFactory and filter in LoggerFor for keyName equals NHibernate.SQL and set via LoggerProvider.SetLoggersFactory. Works for SQLite driver, should work for other.

LoggerProvider by default creates log4net via reflection if log4net assembly presented. So best implementation would be if custom ILoggerFactory will delegate log into default, until NHibernate.SQL log requested.

Answer 4

Just an idea: can you implement a new log4net-appender, which takes all sqlstatements(debug with parameter) and holds the last one. When an error occured you can ask him for the last sqlstatement and email it.