nHibernate SQL logging + stack trace together

Question

I'm having an issue in where records occasionally go missing from our production database. This is a .NET MVC 2 app with nHibernate. It has been worked on by several developers over the last few years so we assume somewhere a mapping was set-up incorrectly and that nHibernate believes it should be deleting these records.

I used log4net to log all SQL generated by nHibernate from both our admin and front-end (in seperate files). Oddly enough it seems the front-end of our site occasionally generates the DELETES for the then missing records. It's odd because although the front-end and back-end share the same data model the front-end shouldn't have any write/update functionality. We were sure it was a bug in admin where all the CRUD is. Yet there it is in the logs... a batch of DELETES.

I would like to get more information about where in the stack these SQL statements are being generated from. If I could somehow get a small stack trace before every nHibernate transaction that would be great. So far my log4net settings look like this:

<appender name="RollingFile" type="log4net.Appender.RollingFileAppender,log4net" >

    <param name="File" value="nHibernate.txt" />
    <param name="AppendToFile" value="true" />
    <param name="DatePattern" value="yyyy.MM.dd" />

    <layout type="log4net.Layout.PatternLayout,log4net">
        <conversionPattern value="%d %p %m%n" />
    </layout>

</appender>

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

Maybe I just need to log the two things separately and compare the times myself? I'm just looking for a suggestion.

Thanks!

Answer 1

You could use stacktrace or stacktracedetail conversion patterns.

stacktrace

Used to output the stack trace of the logging event The stack trace level specifier may be enclosed between braces. For example, %stacktrace{level}. If no stack trace level specifier is given then 1 is assumed. Output uses the format: type3.MethodCall3 > type2.MethodCall2 > type1.MethodCall1. This pattern is not available for Compact Framework assemblies.

stacktracedetail

Used to output the stack trace of the logging event The stack trace level specifier may be enclosed between braces. For example, %stacktracedetail{level}. If no stack trace level specifier is given then 1 is assumed. Output uses the format: type3.MethodCall3(type param,...) > type2.MethodCall2(type param,...) > type1.MethodCall1(type param,...). This pattern is not available for Compact Framework assemblies.

You could use it like this:

<conversionPattern value="%d %p %m%n%stacktrace" />

---

Edit:

Few SO questions on log4net stack trace:
How do you add a StackTrace to every log call in log4net?
How to log stack trace using log4net (C#)
Does log4net support including the call stack in a log message