nhibernate - How to get SQL with parameter values on an exception

Question

Hard to believe, but I can't seem to find a straight answer for this: How can I get the SQL statement including the parameter values when the statement generates an exception and only when it generates an exception. I know how to log the statement+parameters for every SQL generated, but that's way too much. When there's a System.Data.SqlClient.SqlException, though, it only provides the SQL, not the parameter values. How can I catch that at a point where I have access to the that data so that I can log it?

Answer 1

Based on a number of responses to various questions (not just mine), I've cobbled something together that does the trick. I think it could be useful to others as well, so I'm including a good deal of it here:

The basic idea is to

1. Have NH log all queries, pretty-printed and with the parameter values in situ
2. Throw all those logs out except the one just prior to the exception.

I use Log4Net, and the setup is like this:

<?xml version="1.0"?>

<log4net>
  <appender name="RockAndRoll" type="Util.PrettySqlRollingFileAppender, Util">
    <file type="log4net.Util.PatternString" >
      <conversionPattern value="%env{Temp}\%property{LogDir}\MyApp.log" />
    </file>
    <DatePattern value="MM-dd-yyyy" />
    <appendToFile value="true" />
    <immediateFlush value="true" />
    <rollingStyle value="Composite" />
    <maxSizeRollBackups value="10" />
    <maximumFileSize value="100MB" />
    <staticLogFileName value="true" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date %-5level %logger - %message%newline" />
    </layout>
  </appender>

  <appender name="ErrorBufferingAppender" type="log4net.Appender.BufferingForwardingAppender">
    <bufferSize value="2" />
    <lossy value="true" />
    <evaluator type="log4net.Core.LevelEvaluator">
      <threshold value="ERROR" />
    </evaluator>
    <appender-ref ref="RockAndRoll" />
    <Fix value="0" />
  </appender>

  <logger name="NHibernate.SQL">
    <additivity>false</additivity>
    <appender-ref ref="ErrorBufferingAppender" />
    <level value="debug" />
  </logger>

  <logger name="error-buffer">
    <additivity>false</additivity>
    <appender-ref ref="ErrorBufferingAppender" />
    <level value="debug" />
  </logger>

  <root>
    <level value="info" />
    <appender-ref ref="RockAndRoll" />
  </root>

</log4net>

The NHibernate.SQL logger logs all queries to the ErrorBufferingAppender, which keeps throwing them out and saves only the last one in its buffer. When I catch an exception I log one line at ERROR level to logger error-buffer, which passes it to ErrorBufferingAppender which -- because it's at ERROR level -- pushes it, along with the last query, out to RockAndRoll, my RollingFileAppender.

I implemented a subclass of RollingFileAppender called PrettySqlRollingFileAppender (which I'm happy to provide if anyone's interested) that takes the parameters from the end of the query and substitutes them inside the query itself, making it much more readable.