Configure Log4Net for use with NHibernate

Dario Quintana — Fri, 17 Oct 2008 00:23:49 GMT

Current revision posted to How to by Dario Quintana on 16/10/2008 09:23:49 p.m.

Configure Log4Net for use with NHibernate

Filed under: log4net, logging

The Log4Net assebly assembly is distributed with NHibernate binaries.

If you are not sure about details of the configuration shown below please refer to this documentation.

Running without Log4Net

If you only want NHibernate to log the queries it sends to the data source when running unit tests you don't have to configure Log4Net at all. It suffices to add the show_sql key to the NHibernate configuration. If you are using a separate xml file to configure NHibernate (e.g. the hibernate.cfg.xml) then its content might look similar to the one below

<?xml version="1.0" encoding="utf-8" ?>
<hibernate-configuration xmlns="urn:nhibernate-configuration-2.2">
  <session-factory>
    <property name="connection.provider">NHibernate.Connection.DriverConnectionProvider</property>
  <property name="dialect">NHibernate.Dialect.MsSql2005Dialect</property>
  <property name="connection.driver_class">NHibernate.Driver.SqlClientDriver</property>
  <property name="connection.connection_string">
    Server=(local);Database=NHibernateFAQ;Integrated Security=SSPI;
  </property>
  <property name="show_sql">true</property>
  </session-factory>
</hibernate-configuration>

Now when running any unit test that involves NHibernate the queries generated by NHibernate will be logged in the output window (be it the unit test runner of Resharper or be it the Output Window of Visual Studio when you useTestDriven).

Logging with Log4Net

If you want to use Log4Net to collect logging information generated by NHibernate you have to add the necessary configuration to the config file of your application. If you want to log to two different targets (e.g. to the console and to a file) the relevant sections in your config file might look like follows

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <!-- Others sections -->
    <section name="log4net"
      type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />
  </configSections>

  <!-- Some others configurations -->

  <!-- This section contains the log4net configuration settings -->
  <log4net debug="false">

    <!-- Define some output appenders -->
    <appender name="trace"
          type="log4net.Appender.TraceAppender, log4net">
      <layout type="log4net.Layout.PatternLayout,log4net">
        <param name="ConversionPattern"
             value="%d{ABSOLUTE} %-5p %c{1}:%L - %m%n" />
      </layout>
    </appender>

    <appender name="console"
          type="log4net.Appender.ConsoleAppender, log4net">
      <layout type="log4net.Layout.PatternLayout,log4net">
        <param name="ConversionPattern"
             value="%d{ABSOLUTE} %-5p %c{1}:%L - %m%n" />
      </layout>
    </appender>

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

      <param name="File" value="log.txt" />
      <param name="AppendToFile" value="false" />
      <param name="RollingStyle" value="Date" />
      <param name="DatePattern" value="yyyy.MM.dd" />
      <param name="StaticLogFileName" value="true" />

      <layout type="log4net.Layout.PatternLayout,log4net">
        <param name="ConversionPattern"
          value="%d [%t] %-5p %c - %m%n" />
      </layout>
    </appender>

    <!-- Setup the root category, add the appenders and set the default priority -->
    <root>
      <priority value="DEBUG" />
      <appender-ref ref="console" />
    </root>

  </log4net>
</configuration>

Here I define that all output with a priority of at least DEBUG goes to the console.

Now I have to tell my application that I want to use Log4Net. I can do that with an assembly level attribute. That is, you have to put the following code snippet somewhere in your application (e.g. the "Global. asax" if you are building a web application)

// Configure log4net using the .config file
[assembly: log4net.Config.XmlConfigurator(Watch = true)]

having done do we can now run a first unit test that accesses the database via NHibernate. The output generated by Log4Net in the unit test runner is similar to this

2008-07-02 08:40:07,249 INFO NHibernate 2.0.0.4000 (2.0.0.4000)
2008-07-02 08:40:07,251 INFO hibernate-configuration section not found in application configuration file
2008-07-02 08:40:07,254 INFO Bytecode provider name : lcg
2008-07-02 08:40:07,257 INFO Using reflection optimizer
2008-07-02 08:40:08,515 DEBUG connection.provider=NHibernate.Connection.DriverConnectionProvider
2008-07-02 08:40:08,516 DEBUG dialect=NHibernate.Dialect.MsSql2005Dialect
2008-07-02 08:40:08,517 DEBUG connection.driver_class=NHibernate.Driver.SqlClientDriver
2008-07-02 08:40:08,517 DEBUG connection.connection_string=Server=(local);Database=NHibernateFAQ;Integrated Security=SSPI;
2008-07-02 08:40:08,518 DEBUG show_sql=false
2008-07-02 08:40:08,522 DEBUG properties: System.Collections.Generic.Dictionary`2[System.String,System.String]
2008-07-02 08:40:08,526 INFO Mapping resource: LoggingSample.Person.hbm.xml
2008-07-02 08:40:08,872 INFO Using dialect: NHibernate.Dialect.MsSql2005Dialect
2008-07-02 08:40:11,425 INFO Mapping class: LoggingSample.Person -> Person
2008-07-02 08:40:11,537 DEBUG Mapped property: Id -> Id, type: Int32
2008-07-02 08:40:11,612 DEBUG Mapped property: LastName -> LastName, type: String
2008-07-02 08:40:11,614 DEBUG Mapped property: FirstName -> FirstName, type: String
2008-07-02 08:40:11,614 DEBUG Mapped property: Birthdate -> Birthdate, type: DateTime
2008-07-02 08:40:11,632 INFO checking mappings queue
2008-07-02 08:40:11,634 INFO processing one-to-many association mappings
2008-07-02 08:40:11,634 INFO processing one-to-one association property references
2008-07-02 08:40:11,634 INFO processing foreign key constraints
2008-07-02 08:40:11,712 INFO Using dialect: NHibernate.Dialect.MsSql2005Dialect
2008-07-02 08:40:11,716 INFO Using dialect defined converter
...
2008-07-02 08:40:12,410 DEBUG Static SQL for entity: LoggingSample.Person
2008-07-02 08:40:12,411 DEBUG  Version select: SELECT Id FROM Person WHERE Id = ?
2008-07-02 08:40:12,412 DEBUG  Snapshot select: SELECT person_.Id, person_.LastName as LastName0_, person_.FirstName as FirstName0_, person_.Birthdate as Birthdate0_ FROM Person person_ WHERE person_.Id=?
...

as you can see LOADS of information.

To tune the generated logging information a little bit we can filter the output generated by NHibernate by putting the following configuration section into our config file (put them just after the root section inside the log4net node)

    <logger name="NHibernate">
      <level value="WARN" />
    </logger>

    <logger name="NHibernate.SQL">
      <level value="DEBUG" />
    </logger>

Obviously NHibernate defines two different loggers NHibernate and NHibernate.SQL. The first one receives all logging output that NHibernate generates where as the second one only receives the sql statements generated by NHibernate.

With the above settings in place the output generated is reduced to

2008-07-02 08:48:58,636 DEBUG select person0_.Id as Id0_, 
                        person0_.LastName as LastName0_, 
                        person0_.FirstName as FirstName0_, 
                        person0_.Birthdate as Birthdate0_ 
                        from Person person0_

That's what we want. Only if we have some weird problems we need to change the priority level of the NHibernate filter to say INFO or DEBUG.

Configure Log4Net for use with NHibernate

Fabio Maulo — Sun, 07 Sep 2008 17:20:36 GMT

Revision 2 posted to How to by Fabio Maulo on 07/09/2008 02:20:36 p.m.

Configure Log4Net for use with NHibernate

Recently there was a question in the NHUser group about how to configure

The Log4Net to log the queries generated by assebly is distributed with NHibernate . First of all: you can get Log4Net here. There you also find the documentationbinaries.

If you are not sure about details of the configuration shown below please refer to this documentation.

Running without Log4Net

<?xml  version=version="1.0"  encoding=encoding="utf-8" ?><o:p></o:p>
<hibernate-configuration xmlns="urn:nhibernate-configuration-2.2"><o:p></o:p>"urn:nhibernate-configuration-2.2">
  <session-factory><o:p></o:p>
    <property name="connection.provider">"connection.provider">NHibernate.Connection.DriverConnectionProvider</property><o:p></o:p>
  <property name="dialect">"dialect">NHibernate.Dialect.MsSql2005Dialect</property><o:p></o:p>
  <property name="connection.driver_class">"connection.driver_class">NHibernate.Driver.SqlClientDriver</property><o:p></o:p>
  <property name="connection.connection_string">"connection.connection_string">
    Server=(local);Database=NHibernateFAQ;Integrated Security=SSPI;
  </property>   >
  <property name="show_sql">"show_sql">true</property><o:p></o:p>
  </session-factory><o:p></o:p>
</hibernate-configuration><o:p></o:p>

Logging with Log4Net

...

<section name=

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <!-- Others sections -->
    <section name="log4net"type=
      type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />
  </configSections>
 
  <log4net>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender,

  </configSections>

  <!-- Some others configurations -->

  <!-- This section contains the log4net ">
     
<layout type="log4net.Layout.PatternLayout,
configuration settings -->
  <log4net ">
       
<param name=debug="false">

    <!-- Define some output appenders -->
    <appender name="trace"
          type="log4net.Appender.TraceAppender, log4net">
      <layout type="log4net.Layout.PatternLayout,log4net">
        <param name="ConversionPattern"value="%d

             value="%d{ABSOLUTE} %p -5p %c{1}:%L - %m%n" />
     
</layout>
    </appender>
 
    <appender name="RollingFile" type=
      </layout>
    </appender>

    <appender name="console"
          type="log4net.Appender.ConsoleAppender, log4net">
      <layout type="log4net.Layout.PatternLayout,log4net">
        <param name="ConversionPattern"
             value="%d{ABSOLUTE} %-5p %c{1}:%L - %m%n" />
      </layout>
    </appender>

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

      <param name="File"value= value="log.txt" />
     
<param name=
      <param name="AppendToFile"value="true"  value="false" />
     
<param name=
      <param name="RollingStyle" value="Date" />
      <param name="DatePattern"value= value="yyyy.MM.dd" />
 
     
<layout type="log4net.Layout.PatternLayout,log4net">
       
<conversionPattern value=
      <param name="StaticLogFileName" value="true" />

      <layout type="log4net.Layout.PatternLayout,log4net">
        <param name="ConversionPattern"
          value="%d [%t] %p -5p %c - %m%n" />
     
</layout>
    </appender>
 
    <root>
     
<priority value=
      </layout>
    </appender>

    <!-- Setup the root category, add the appenders and set the default priority -->
    <root>
      <priority value="DEBUG" />
     
<appender-ref ref="ConsoleAppender" 
      <appender-ref ref="console" />
    </root>
   
...
</configuration>
    </root>

  </log4net>
</configuration>

Here I define that all output with a priority of at least DEBUG goes to the console.

// Configure log4net using the .config file
[assembly: log4net.Config.XmlConfigurator(Watch = true)true)]

having done do we can now run a first unit test that accesses the database via NHibernate. The output generated by Log4Net in the unit test runner is similar to this

2008-07-02 08:40:07,249 INFO NHibernate 2.0.0.1001 2.0.0.4000 (2.0.0.1001)2.0.0.4000)
2008-07-02 08:40:07,251 INFO hibernate-configuration section not found in application configuration file
2008-07-02 08:40:07,254 INFO Bytecode provider name : lcg
2008-07-02 08:40:07,257 INFO Using reflection optimizer
2008-07-02 08:40:08,515 DEBUG connection.provider=NHibernate.Connection.DriverConnectionProvider
2008-07-02 08:40:08,516 DEBUG dialect=NHibernate.Dialect.MsSql2005Dialect
2008-07-02 08:40:08,517 DEBUG connection.driver_class=NHibernate.Driver.SqlClientDriver
2008-07-02 08:40:08,517 DEBUG connection.connection_string=Server=(local);Database=NHibernateFAQ;Integrated Security=SSPI;
2008-07-02 08:40:08,518 DEBUG show_sql=false
2008-07-02 08:40:08,522 DEBUG properties: System.Collections.Generic.Dictionary`2[System.String,System.String]
2008-07-02 08:40:08,526 INFO Mapping resource: LoggingSample.Person.hbm.xml
2008-07-02 08:40:08,872 INFO Using dialect: NHibernate.Dialect.MsSql2005Dialect
2008-07-02 08:40:11,425 INFO Mapping class: LoggingSample.Person -> Person
2008-07-02 08:40:11,537 DEBUG Mapped property: Id -> Id, type: Int32
2008-07-02 08:40:11,612 DEBUG Mapped property: LastName -> LastName, type: String
2008-07-02 08:40:11,614 DEBUG Mapped property: FirstName -> FirstName, type: String
2008-07-02 08:40:11,614 DEBUG Mapped property: Birthdate -> Birthdate, type: DateTime
2008-07-02 08:40:11,632 INFO checking mappings queue
2008-07-02 08:40:11,634 INFO processing one-to-many association mappings
2008-07-02 08:40:11,634 INFO processing one-to-one association property references
2008-07-02 08:40:11,634 INFO processing foreign key constraints
2008-07-02 08:40:11,712 INFO Using dialect: NHibernate.Dialect.MsSql2005Dialect
2008-07-02 08:40:11,716 INFO Using dialect defined converter
...
2008-07-02 08:40:12,410 DEBUG Static SQL for entity: LoggingSample.Person
2008-07-02 08:40:12,411 DEBUG  Version select: SELECT Id FROM Person WHERE Id = ?
2008-07-02 08:40:12,412 DEBUG  Snapshot select: SELECT person_.Id, person_.LastName as LastName0_, person_.FirstName as FirstName0_, person_.Birthdate as Birthdate0_ FROM Person person_ WHERE person_.Id=?
...

as you can see LOADS of information.

<logger name=

    <logger name="NHibernate"additivity="false">
  <level value="WARN"/>      
  <appender-ref ref="RollingFile" />
  <appender-ref ref="ConsoleAppender" 
      <level value="WARN" />
</logger>
 
<logger name=
    </logger>

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

With the above settings in place the output generated is reduced to

2008-07-02 08:48:58,636 DEBUG select person0_.Id as Id0_, 
                        person0_.LastName as LastName0_, 
                        person0_.FirstName as FirstName0_, 
                        person0_.Birthdate as Birthdate0_ 
                        from Person person0_

That's what we want. Only if we have some weird problems we need to change the priority level of the NHibernate filter to say INFO or DEBUG.

As usual you can find a demo solution here.

Configure Log4Net for use with NHibernate

gabriel.schenker — Sun, 07 Sep 2008 05:09:37 GMT

Revision 1 posted to How to by gabriel.schenker on 07/09/2008 02:09:37 a.m.

Recently there was a question in the NHUser group about how to configure Log4Net to log the queries generated by NHibernate. First of all: you can get Log4Net here. There you also find the documentation. If you are not sure about details of the configuration shown below please refer to this documentation.

Running without Log4Net

<?xml version="1.0" encoding="utf-8" ?><o:p></o:p>

<hibernate-configuration xmlns="urn:nhibernate-configuration-2.2"><o:p></o:p>

<session-factory><o:p></o:p>

<property name="connection.provider">NHibernate.Connection.DriverConnectionProvider</property><o:p></o:p>

<property name="dialect">NHibernate.Dialect.MsSql2005Dialect</property><o:p></o:p>

<property name="connection.driver_class">NHibernate.Driver.SqlClientDriver</property><o:p></o:p>

<property name="connection.connection_string">Server=(local);Database=NHibernateFAQ;Integrated Security=SSPI;</property>

</session-factory><o:p></o:p>

</hibernate-configuration><o:p></o:p>

Now when running any unit test that involves NHibernate the queries generated by NHibernate will be logged in the output window (be it the unit test runner of Resharper or be it the Output Window of Visual Studio when you useTestDriven).

Logging with Log4Net

...

</configSections>

</layout>

</appender>

</layout>

</appender>

<root>

<appender-ref ref="ConsoleAppender" />

</root>

...

</configuration>

Here I define that all output with a priority of at least DEBUG goes to the console.

// Configure log4net using the .config file

[assembly: log4net.Config.XmlConfigurator(Watch = true)]

having done do we can now run a first unit test that accesses the database via NHibernate. The output generated by Log4Net in the unit test runner is similar to this

2008-07-02 08:40:07,249 INFO NHibernate 2.0.0.1001 (2.0.0.1001)

2008-07-02 08:40:07,251 INFO hibernate-configuration section not found in application configuration file

2008-07-02 08:40:07,254 INFO Bytecode provider name : lcg

2008-07-02 08:40:07,257 INFO Using reflection optimizer

2008-07-02 08:40:08,515 DEBUG connection.provider=NHibernate.Connection.DriverConnectionProvider

2008-07-02 08:40:08,516 DEBUG dialect=NHibernate.Dialect.MsSql2005Dialect

2008-07-02 08:40:08,517 DEBUG connection.driver_class=NHibernate.Driver.SqlClientDriver

2008-07-02 08:40:08,517 DEBUG connection.connection_string=Server=(local);Database=NHibernateFAQ;Integrated Security=SSPI;

2008-07-02 08:40:08,518 DEBUG show_sql=false

2008-07-02 08:40:08,522 DEBUG properties: System.Collections.Generic.Dictionary`2[System.String,System.String]

2008-07-02 08:40:08,526 INFO Mapping resource: LoggingSample.Person.hbm.xml

2008-07-02 08:40:08,872 INFO Using dialect: NHibernate.Dialect.MsSql2005Dialect

2008-07-02 08:40:11,425 INFO Mapping class: LoggingSample.Person -> Person

2008-07-02 08:40:11,537 DEBUG Mapped property: Id -> Id, type: Int32

2008-07-02 08:40:11,612 DEBUG Mapped property: LastName -> LastName, type: String

2008-07-02 08:40:11,614 DEBUG Mapped property: FirstName -> FirstName, type: String

2008-07-02 08:40:11,614 DEBUG Mapped property: Birthdate -> Birthdate, type: DateTime

2008-07-02 08:40:11,632 INFO checking mappings queue

2008-07-02 08:40:11,634 INFO processing one-to-many association mappings

2008-07-02 08:40:11,634 INFO processing one-to-one association property references

2008-07-02 08:40:11,634 INFO processing foreign key constraints

2008-07-02 08:40:11,712 INFO Using dialect: NHibernate.Dialect.MsSql2005Dialect

2008-07-02 08:40:11,716 INFO Using dialect defined converter

...

2008-07-02 08:40:12,410 DEBUG Static SQL for entity: LoggingSample.Person

2008-07-02 08:40:12,411 DEBUG Version select: SELECT Id FROM Person WHERE Id = ?

2008-07-02 08:40:12,412 DEBUG Snapshot select: SELECT person_.Id, person_.LastName as LastName0_, person_.FirstName as FirstName0_, person_.Birthdate as Birthdate0_ FROM Person person_ WHERE person_.Id=?

...

as you can see LOADS of information.

<appender-ref ref="RollingFile" />

<appender-ref ref="ConsoleAppender" />

</logger>

<appender-ref ref="RollingFile" />

<appender-ref ref="ConsoleAppender" />

</logger>

With the above settings in place the output generated is reduced to

2008-07-02 08:48:58,636 DEBUG select person0_.Id as Id0_,

person0_.LastName as LastName0_,

person0_.FirstName as FirstName0_,

person0_.Birthdate as Birthdate0_

from Person person0_

That's what we want. Only if we have some weird problems we need to change the priority level of the NHibernate filter to say INFO or DEBUG.

As usual you can find a demo solution here.