4.5. Logging SqlMap Activity

The iBATIS DataMapper framework records its interaction with the database through an internal logging mechanism patterned after Apache Log4Net. The internal logging mechanism can use one of the three built-in loggers (NoOpLogger, ConsoleOutLogger, TraceLogger) or external logging packages such as Apache Log4Net. In order for iBATIS to generate log messages, the application's config file (App.Config or Web.Config) must contain an appropriate configSection node:

Example 4.27. iBATIS Configuration Section Handler for logging

<configSections>
 <sectionGroup name="iBATIS">
  <section name="logging" type="IBatisNet.Common.Logging.ConfigurationSectionHandler, IBatisNet.Common" />
 </sectionGroup>
</configSections>

The application's config file must declare one logger implementation. See the examples below on how to configure one of the three built-in loggers.

<iBATIS>
 <logging>
  <logFactoryAdapter type="IBatisNet.Common.Logging.Impl.ConsoleOutLoggerFA, IBatisNet.Common">
   <arg key="showLogName" value="true" />
   <arg key="showDataTime" value="true" />
   <arg key="level" value="ALL" />
   <arg key="dateTimeFormat" value="yyyy/MM/dd HH:mm:ss:SSS" />
  </logFactoryAdapter>
 </logging>
</iBATIS>
<iBATIS>
 <logging>
  <logFactoryAdapter type="IBatisNet.Common.Logging.Impl.NoOpLoggerFA, IBatisNet.Common" />
 </logging>
</iBATIS>
<iBATIS>
 <logging>
  <logFactoryAdapter type="IBatisNet.Common.Logging.Impl.TraceLoggerFA, IBatisNet.Common" />
 </logging>
</iBATIS>

To configure iBATIS to use another logger implementation, simple specify the appropriate logFactoryAdapter type. To use Apache Log4Net with the iBATIS DataMapper framework, use the following configuration setting:

<iBATIS>
 <logging>
  <logFactoryAdapter type="IBatisNet.Common.Logging.Impl.Log4NetLoggerFA, IBatisNet.Common.Logging.Log4Net">
   <arg key="configType" value="inline" />
  </logFactoryAdapter>
 </logging>
</iBATIS>
<iBATIS>
 <logging>
  <logFactoryAdapter type="IBatisNet.Common.Logging.Impl.Log4NetLoggerFA, IBatisNet.Common.Logging.Log4Net">
   <arg key="configType" value="file" />
   <arg key="configFile" value="log4Net.config" />
  </logFactoryAdapter>
 </logging>
</iBATIS>

The Log4NetLoggerFA supports the following values for the configTypes argument:

Table 4.12. Valid configType values

configTypeDescription
inlinelog4net node will use the log4net node in the App.Config/Web.Config file when it is configured
file(also requires configFile argument) - log4net will use an external file for its configuration
file-watch (also requires configFile argument) - log4net will use an external file for its configuration and will re-configure itself if this file changes
externaliBATIS will not attempt to configure log4net.


4.5.1. Sample Logging Configurations

The simplest logging configuration is to output log messages to Console.Out:

<configuration>
 <configSections>
  <sectionGroup name="iBATIS">
   <section name="logging" type="IBatisNet.Common.Logging.ConfigurationSectionHandler, IBatisNet.Common" />
  </sectionGroup>
 </configSections>
 <iBATIS>
  <logging>
   <logFactoryAdapter type="IBatisNet.Common.Logging.Impl.ConsoleLoggerFA, IBatisNet.Common.Logging" />
  </logging>
 </iBATIS>
</configuration>

A common logging configuration is to use Apache Log4Net. To use Log4Net with your own application, you need to provide your own Log4Net configuration. You can do this by adding a configuration file for your assembly that includes a <log4Net> element. The configuration file is named after your assembly but adds a .config extension, and is stored in the same folder as your assembly. This is an example of a basic Log4Net configuration block (IBatisNet.DataMapper.Test.dll.Config) that also creates a log4net.txt which contains debug information from log4net. If log4net is not producing output, check the log4net.txt file.

<configuration>
 <configSections>
  <sectionGroup name="iBATIS">
   <section name="logging" type="IBatisNet.Common.Logging.ConfigurationSectionHandler, IBatisNet.Common" />
  </sectionGroup>
  <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
 </configSections>
 <appSettings>
  <add key="log4net.Internal.Debug" value="true"/>
 </appSettings>
 <system.diagnostics>
 <trace autoflush="true">
   <listeners>
    <add name="textWriterTraceListener" 
     type="System.Diagnostics.TextWriterTraceListener"
     initializeData="C:\\inetpub\\wwwroot\\log4net.txt" />
   </listeners>
  </trace>
 </system.diagnostics>
 <iBATIS>
  <logging>
   <logFactoryAdapter type="IBatisNet.Common.Logging.Impl.Log4NetLoggerFA, IBatisNet.Common.Logging.Log4Net">
    <arg key="configType" value="inline" />
   </logFactoryAdapter>
  </logging>
 </iBATIS>
 <log4net>
  <appender name="FileAppender" type="log4net.Appender.FileAppender">
   <file value="log.txt" />
   <appendToFile value="true" />
   <layout type="log4net.Layout.SimpleLayout" />
  </appender>
  <root>
   <level value="ALL" />
   <appender-ref ref="FileAppender" />
  </root>
 </log4net>
</configuration>

Example 4.28. A complete Log4Net configuration block (IBatisNet.DataMapper.Test.dll.Config)

<configuration>
 <!-- Register a section handler for the log4net section -->
 <configSections>
  <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
 </configSections>
 <appSettings>
  <!-- To enable internal log4net logging specify the following appSettings key -->
  <!-- <add key="log4net.Internal.Debug" value="true"/> -->
 </appSettings>

 <!-- This section contains the log4net configuration settings -->
 <log4net>
  <!-- Define some output appenders -->
  <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
   <param name="File" value="log.txt" />
   <param name="AppendToFile" value="true" />
   <param name="MaxSizeRollBackups" value="2" />
   <param name="MaximumFileSize" value="100KB" />
   <param name="RollingStyle" value="Size" />
   <param name="StaticLogFileName" value="true" />
   <layout type="log4net.Layout.PatternLayout">
    <param name="Header" value="[Header]\r\n" />
    <param name="Footer" value="[Footer]\r\n" />
    <param name="ConversionPattern" value="%d [%t] %-5p %c [%x] - %m%n" />
   </layout>
  </appender>
  <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
   <layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%d [%t] %-5p %c [%x] &lt;%X{auth}&gt; - %m%n" />
   </layout>
  </appender>

  <!-- OFF, FATAL, ERROR, WARN, INFO, DEBUG, ALL -->
  <!-- Set root logger level to ERROR and its appenders -->
  <root>
   <level value="ERROR" />
   <appender-ref ref="RollingLogFileAppender" />
   <appender-ref ref="ConsoleAppender" />
  </root>

  <!-- Print only messages of level DEBUG or above in the packages -->
  <logger name="IBatisNet.DataMapper.Commands.DefaultPreparedCommand">
   <level value="DEBUG" />
  </logger>
  <logger name="IBatisNet.DataMapper.Configuration.Cache.CacheModel">
   <level value="DEBUG" />
  </logger>
  <logger name="IBatisNet.DataMapper.LazyLoadList">
   <level value="DEBUG" />
  </logger>
  <logger name="IBatisNet.DataMapper.SqlMapSession">
   <level value="DEBUG" />
  </logger>
  <logger name="IBatisNet.Common.Transaction.TransactionScope">
   <level value="DEBUG" />
  </logger>
  <logger name="IBatisNet.DataAccess.DaoSession">
   <level value="DEBUG" />
  </logger>
  <logger name="IBatisNet.DataAccess.Configuration.DaoProxy">
   <level value="DEBUG" />
  </logger>
  <logger name="IBatisNet.DataMapper.Configuration.Statements.PreparedStatementFactory">
   <level value="OFF" />
  </logger>
  <logger name="IBatisNet.DataMapper.Commands.IPreparedCommand">
   <level value="OFF" />
  </logger>  
 </log4net>
</configuration>

To log all Prepared SQL command text, enable the logger for IBatisNet.DataMapper.Configuration.Statements.DefaultPreparedCommand. This will display the statement, parameters, and parameter types used by the DataMapper.

Example 4.29. Sample DefaultPreparedCommand logger output

2005-06-08 01:39:33 [3872] DEBUG IBatisNet.DataMapper.Commands.DefaultPreparedCommand - 
Statement Id: [User.Update] PreparedStatement : [UPDATE [User] SET [DateLastUpdated] = NOW() WHERE [UserId] = ?]
2005-06-08 01:39:43 [3872] DEBUG IBatisNet.DataMapper.Commands.DefaultPreparedCommand - 
Statement Id: [User.Update] Parameters: [param0=[UserId,1]]
2005-06-08 01:39:53 [3872] DEBUG IBatisNet.DataMapper.Commands.DefaultPreparedCommand - 
Statement Id: [User.Update] Types: [param0=[String, System.Int32]]

If your statements are named the same across all sqlMap files, its possible to filter log messages when using Apache Log4Net. The example below only logs Insert, Update, and Delete statements sent to the database. Select or GetMany statements are not logged:

Example 4.30. Sample Apache Log4Net appender node that will log Insert, Update, and Delete statements to a file

<appender name="FileAppender" type="log4net.Appender.FileAppender">
 <file value="InsertsUpdatesDeletes.txt" />
 <layout type="log4net.Layout.SimpleLayout" />
 <filter type="log4net.Filter.StringMatchFilter">
  <regExToMatch value="^(?!Statement Id:)|Statement Id: \[\w+?\.(?:Insert|Update|Delete)" />
 </filter>
 <filter type="log4net.Filter.DenyAllFilter" />
</appender>


If you would like to log cache usage in your application, enable the logger for IBatisNet.DataMapper.Configuration.Cache.CacheModel.

Example 4.31. Sample CacheModel logger output

2005-06-08 01:38:34,403 [3648] DEBUG IBatisNet.DataMapper.Configuration.Cache.CacheModel - 
Flush cacheModel named Account.account-cache for statement 'UpdateAccountViaParameterMap'

To keep track of DataMapper session information, enable the logger for IBatisNet.DataMapper.SqlMapSession.

Example 4.32. Sample SqlMapSession logger output

2005-06-08 01:39:42,660 [3872] DEBUG IBatisNet.DataMapper.SqlMapSession [] - 
  Open Connection "3194" 
  to "Microsoft SQL Server 7.0/2000, provider V1.0.5000.0 in framework .NET V1.1".
2005-06-08 01:39:42,660 [3872] DEBUG IBatisNet.DataMapper.Commands.DefaultPreparedCommand [] - 
  PreparedStatement : [select * from Orders where Order_ID =  @param0 ]
2005-06-08 01:39:42,660 [3872] DEBUG IBatisNet.DataMapper.Commands.DefaultPreparedCommand [] - 
  Parameters: [@param0=[value,1]]
2005-06-08 01:39:42,660 [3872] DEBUG IBatisNet.DataMapper.Commands.DefaultPreparedCommand [] - 
  Types: [@param0=[Int32, System.Int32]]
2005-06-08 01:39:42,676 [3872] DEBUG IBatisNet.DataMapper.SqlMapSession [] - 
  Close Connection "3194" to 
  "Microsoft SQL Server 7.0/2000, provider V1.0.5000.0 in framework .NET V1.1".

To get information about lazyload usage by the DataMapper, enable the logger for IBatisNet.DataMapper.LazyLoadList.

Example 4.33. Sample LazyLoadList logger output

2005-06-08 01:39:42,316 [3872] DEBUG IBatisNet.DataMapper.LazyLoadList [] - 
  Proxyfying call to get_Count
2005-06-08 01:39:42,316 [3872] DEBUG IBatisNet.DataMapper.LazyLoadList [] - 
  Proxyfying call, query statement GetLineItemsForOrder
2005-06-08 01:39:42,316 [3872] DEBUG IBatisNet.DataMapper.SqlMapSession [] - 
  Open Connection "3463" to 
  "Microsoft SQL Server 7.0/2000, provider V1.0.5000.0 in framework .NET V1.1".
2005-06-08 01:39:42,316 [3872] DEBUG IBatisNet.DataMapper.Commands.DefaultPreparedCommand [] - 
  PreparedStatement : [select LineItem_ID as Id, LineItem_Code as Code,      
  LineItem_Quantity as Quantity, LineItem_Price as Price     
  from LineItems where Order_ID =  @param0 ]
2005-06-08 01:39:42,316 [3872] DEBUG IBatisNet.DataMapper.Commands.DefaultPreparedCommand [] - 
  Parameters: [@param0=[value,1]]
2005-06-08 01:39:42,316 [3872] DEBUG IBatisNet.DataMapper.Commands.DefaultPreparedCommand [] - 
  Types: [@param0=[Int32, System.Int32]]
2005-06-08 01:39:42,316 [3872] DEBUG IBatisNet.DataMapper.SqlMapSession [] - 
  Close Connection "3463" to 
  "Microsoft SQL Server 7.0/2000, provider V1.0.5000.0 in framework .NET V1.1".
2005-06-08 01:39:42,316 [3872] DEBUG IBatisNet.DataMapper.LazyLoadList [] - 
  End of proxyfied call to get_Count