Diagnostic Tracing with BizTalk 2004

Diagnostic Tracing with BizTalk 2004

Early on when working with BizTalk 2004, it might be tempting to view the ability to track orchestration events (and the use of the orchestration debugger) as a substitute for traditional diagnostic logging. 

After all, the orchestration debugger can tell you exactly how far you got in an orchestration, and what path through the workflow you took to get there.   

However, consider these limitations:

·         The orchestration debugger is used either a) after the orchestration has completed or b) in conjunction with a breakpoint.  Neither of these choices is ideal, and only the latter gives you visibility into the intermediate values of variables/messages.

·         Once an orchestration involves looping constructs, multiple orchestrations connected via messaging, etc. the orchestration debugger often loses quite a bit of diagnostic value. 

Given this, it can be useful to integrate diagnostic logging into your orchestrations and the components they call.  If we are going to invest in this effort, we’d like to use something richer than the built-in System.Diagnostics.Trace/Debug infrastructure. 

Log4net is an Apache-sponsored initiative within the “Apache Logging Services” project.  It provides a rich diagnostic infrastructure for .NET, with support for hierarchical logging and configuration, multiple logging targets, and support for logging context.   

A recent article outlined the advantages of log4net over Microsoft’s Enterprise Instrumentation Framework (EIF), though Microsoft/Avanade will be revamping this logging infrastructure with the release of the Enterprise Template Library.   

Given that the log4net initiative has broad support at the API layer (i.e. log4j, log4PLSQL, etc.) and platform layer (including .NET CF) as well as the benefit of maturity, log4net seems like a very reasonable choice for instrumenting BizTalk 2004 applications.  (The Enterprise Template Library logging component will likely be a good choice as well when released.)   

Following is a discussion of log4net itself, along with what is required to use it in a BizTalk 2004 setting. 

Quick Insight into log4net 

Without diving immediately into the log4net API, let’s get a sense for what it can do.  What do we mean by hierarchical logging and configuration with multiple target support? 

Suppose we have classes with these namespace-qualified names:

MyCompany.MyDepartment.MyClassA

MyCompany.MyDepartment.MyClassB 

Each of these classes can obtain a logger specific to their class by declaring a static member as such:

private static readonly ILog log = LogManager.GetLogger(typeof(Foo));

Each class (MyClassA/MyClassB) can now emit trace with statements such as log.Info(“hello world”) or log.Warn(“a potential problem…”).  Default log levels include: Debug, Info, Warn, Error, and Fatal (though these can be expanded.) 

The concept of “context” can be added to a stream of trace messages via NDC.Push(“some context”)/NDC.Pop or MDC.Set(“somekey”,”somevalue”).  (These class names are short for “Nested Diagnostic Context” and “Mapped Diagnostic Context” respectively.)  These can be extremely useful for multithreaded/multi-user applications, to distinguish the streams of related trace messages from each other.  This context can be optionally formatted into the associated tracing statements, as will be shown shortly. 

If we want to turn on tracing at the ‘Error’ level by default, at the ‘Warn’ level for MyCompany, and at the ‘Debug’ level for MyClassA, we would simply configure as follows (notice the use of the namespace hierarchy): 

       <root>

              <level value="ERROR" />

       </root>

       <logger name="MyCompany">

              <level value="WARN" />

       </logger>

       <logger name="MyCompany.MyDepartment.MyClassA">

              <level value="DEBUG" />

       </logger> 

This can be changed on-demand simply by changing the configuration file, which can be reloaded automatically without restarting the application.  This allows us to a) not be blinded by too much trace information and b) not impose undue server load by tracing, whereas a non-hierarchical approach only allows for one logging level for an entire application. 

Suppose it is desired to route all trace information (by default) to OutputDebugString, where a utility such as dbmon.exe or DebugView can be used to view it.  Suppose further it is desired to prefix our output with the date, thread Id, logging level, the name of the logger (i.e. MyCompany.MyDepartment.MyClassA), and the current context.  To do this with log4net, we would have our configuration file declare an “appender” of the appropriate type, and include a declaration of a “layout” as follows.  The “appender” is then referenced by a particular logger (or the root logger). 

<appender name="OutputDebugStringAppender" type="log4net.Appender.OutputDebugStringAppender" >

         <layout type="log4net.Layout.PatternLayout">

                 <!-- The format specifiers let us add a wide variety of additional info -->

                  <param name="ConversionPattern" value="%d [%t] %-5p %c [%x] - %m%n" />

         </layout>

</appender>

<root>

<level value="ERROR" />

<appender-ref ref="OutputDebugStringAppender" />

</root> 

This might yield trace output as follows:

16:39:33,022 [316] INFO  MyCompany.MyDepartment.MyClassA [SomeContext] - Hello World 

Again, the specifics of what additional information can be included in trace output can all be configured dynamically at runtime.  Note that other useful information such as method name, file name, line number, caller’s window identity can all be added with the PatternLayout class as well, though it is quite expensive (further adding value to the hierarchy concept!) 

Moreover, each element of the hierarchy can be directed to a different appender, or to multiple appenders.  Built in appenders include support for ADO.NET, .NET remoting, SMTP, files, rolling files, buffering, and the Event Log (among others.)  Because the Event Log is supported, there is no need to use a separate API to support such logging. 

Core log4net Concepts 

Without attempting to present a full tutorial (see this introduction for a more complete discussion), the core concepts in log4net include: 

Loggers: Use by code to emit trace output at various levels.   

• Loggers are organized into hierarchies just like .NET namespaces (they don't have to correspond, but often should.)  Example: System is parent of System.Text, and an ancestor of System.Text.StringBuilder. 
  • It is typical to have the logger name equal to a fully-qualified class name. 

• Loggers are retrieved using a static method of LogManager, e.g. LogManager.GetLogger(someStringOrTypeName);
  • An ILog interface is returned with Debug, Info, Warn, Error, Fatal methods on it for tracing. 

• Logging level is generally inherited from the hierarchy, and be configured anywhere in the hierarchy. 
  • Rule: logging level is equal to first non-null value working UP the tree.
  • Predefined levels: DEBUG, INFO, WARN, ERROR, FATAL, ALL, OFF
  • Default level for root in hierarchy is DEBUG 

Appenders: An output destination for logging. 

• Built in: event log, asp.net trace, console, file, rolling file, smtp, etc.
• Appenders can optionally have "layouts" to specialize how formatting is done and add additional information (windows identity, source code info, context, thread id, timestamp, etc.) 

• Appenders are attached to a logger.  Log requests will go to a given logger's appender, as well as all appenders attached up the hierarchy (unless "additivity=false" at some level, in which case moving up hierarchy stops…) 

Filters: A given appender can apply a filter such that only log requests that match some criteria will actually be output.  Filters are applied sequentially.  Built-in filters include string match and regex match. 

Configurators: Classes which initialize the log4net environment.  Configuration is done either through assembly attributes that specify a config file, or an explicit call to specify a config file.  The config file can be a standard .net config file, or standalone.  Configuration is by default at the appdomain level, but can be finer-grained through the use of log4net "logging domains".

 

Using log4net with BizTalk 2004 

There are a few challenges to using log4net in a BizTalk 2004 environment.  They can be summarized as follows: 

• Assembly-attribute-driven configuration won’t work because BizTalk 2004 does not appear to support the addition of custom attributes for BizTalk assemblies.  (And even if it did, this method would pose issues for BizTalk environments.)  
• Using the log4net configuration classes for configuration is problematic because there is no clear point at which to make the call.  (How does as an orchestration know if it is “first” and should initialize?  How does it know at any point in an orchestration whether the BizTalk service has been recently recycled, losing the log4net configuration?)  Moreover, there is not a good way to identify where the configuration file should be located.
• ILog-derived classes (log4net loggers) are not serializable “out-of-the-box”, making it difficult to use them in an orchestration setting.
• Log4net context-storage mechanisms are thread-relative, which isn’t workable for orchestrations, since orchestrations often a) dehydrate and then re-hydrate on a different thread and b) make use of parallel branches.  We’d like to correctly associate context such as the orchestration instance ID on a logger that is scoped to an orchestration. 

To address these challenges, I’ve created extensions to log4net that attempt to stay within log4net’s design intent.  These are housed in an assembly called “log4net.Ext.Serializable”. 

The main classes defined are as follows: 

SLog: A serializable implementation of the ILog interface, to be used by orchestrations (or other components) for logging.  This class has an InstanceId property as well as a general properties collection that is carried with the logger itself.  (These can be made available in appender output via a PatternLayout class and the %P{yourpropname} format specifier.  Use %P{InstanceId} for the InstanceId.)  When deserialized, this class can detect an un-initialized state for log4net and recreate the correct configuration. 

SLogManager: To be used in place of log4net’s LogManager to dispense SLog classes.  This is the accepted way of dispensing custom loggers in log4net’s design. 

RegistryConfigurator: A class which consults a registry key for the location of a log4net config file, and creates the configuration in the specified “logging domain” using the log4net DomConfigurator class. 

Specifics for BizTalk 2004 Usage 

Using the assembly just discussed, the specifics of using log4net with a particular BizTalk project can be described as follows: 

·         Get 1.2.0 Beta8 of log4net at http://sourceforge.net/project/showfiles.php?group id=31983&release id=171808. 

·         Get the log4net extension described above, as well as a full sample project if you like. 

·         If you are using NAnt to deploy your BizTalk solution, extend your customDeployTarget as show below to create a registry key that will point to a log4net configuration file within your project’s root directory (whether on a developer desktop or an MSI base directory).  Create a file with the log4net extension that corresponds to your solution name (i.e. BizTalkSample.log4net) 

<target name="customDeployTarget"> 

<!-- Write registry key with location of our log4net configuration file. -->

<exec program="cscript.exe"

failonerror="true"

commandline="/nologo ${deployTools}\WriteRegValue.vbs HKLM\SOFTWARE\${nant.project.name}\log4netConfig ${nant.project.basedir}\${nant.project.name}.log4net" />

 </target>

 ·      Orchestration assemblies should reference log4net.Ext.Serializable as well as log4net.dll, and declare a variable in each orchestration (perhaps named “logger”) of type log4net.Ext.Serializable.SLog.   ·      Orchestrations should begin (after an activating receive, if necessary) with an expression shape that looks like: 

logger = log4net.Ext.Serializable.SLogManager.GetLogger(@"BizTalkSample",log4net.helpers.CallersTypeName.Name);

logger.RegistryConfigurator();

logger.InstanceId = MyOrchName(Microsoft.XLANGs.BaseTypes.InstanceId);

logger.Debug("New request arrived...");

 

Important: If an orchestration has parallel branches, you will want to declare multiple variables of type log4net.Ext.Serializable.SLog, assigning 2-n to the first one, as in:

logger2 = logger;

This prevents the need for synchronizing scopes.  (See this article for more.)

 

·         At various points in your orchestration, simply make calls to logger.Debug/logger.Info/logger.Error, etc.  Rely on logger.Error for event log entries (with appropriate logger/appender configuration.) 

·         Use log4net with the components that your orchestration calls as well.  If those components are serializable, they will want to make use of SLogManager/SLog classes as well in non-static methods.  If you want context (such as the orchestration instance ID) to flow, it might be worthwhile to make an SLog-typed property visible on the class that the orchestration can set.  (This needs more thought.) 

 

Using log4net with Paul Bunyan 

Paul Bunyan is a logging tool that has a very nice server-side buffering service as well as a great trace-viewing client that can connect to multiple servers simultaneously (a great plus for BizTalk groups!)  Although Paul Bunyan has its own API, we aren’t interested in it for purposes of this discussion.   

A log4net appender can be easily written for Paul Bunyan, such that log output can be directed there.  Moreover, this appender can be made to explicitly recognize an InstanceId property carried with a log4net logging event, and map it to the “Context” concept within Paul Bunyan!  This allows for viewing the orchestration instance ID within a distinct, filterable column in the Paul Bunyan viewer as such: 

 

Sample .log4net configuration File 

Note that types have to be referred to with fully-qualified names since log4net.dll is being deployed to and loaded from the GAC. 

<?xml version="1.0" encoding="utf-8" ?>

<log4net> 

       <!-- Define some output appenders -->     

       <appender name="OutputDebugString"

              type="log4net.Appender.OutputDebugStringAppender, log4net, Version=1.2.0.30714,Culture=Neutral,PublicKeyToken=b32731d11ce58905">

 

          <layout type="log4net.Layout.PatternLayout, log4net, Version=1.2.0.30714,Culture=Neutral,PublicKeyToken=b32731d11ce58905">

                 <param name="ConversionPattern" value="%d [%t] %-5p %c - %m [%P{InstanceId}]%n" />

          </layout> 

   </appender>  

   <appender name="EventLog"

      type="log4net.Appender.EventLogAppender, log4net, Version=1.2.0.30714, Culture=Neutral, PublicKeyToken=b32731d11ce58905">         

          <param name="ApplicationName" value="BizTalkSample" /> 

          <layout type="log4net.Layout.PatternLayout, log4net, Version=1.2.0.30714,Culture=Neutral,PublicKeyToken=b32731d11ce58905">

                 <param name="ConversionPattern" value="[%t] %-5p %c - %m [%P{InstanceId}]%n" />

          </layout>     

      <!-- Only send error/fatal messages to the event log. -->

      <filter type="log4net.Filter.LevelRangeFilter">

             <param name="LevelMin" value="ERROR" />

             <param name="LevelMax" value="FATAL" />

      </filter>

   </appender> 

       <!-- Setup the root category, add the appenders and set the default level -->

       <root>

              <!-- Possible levels (in order of increasing detail):

                     OFF, FATAL, ERROR, WARN, INFO, DEBUG, ALL -->

              <level value="ERROR" />

              <appender-ref ref="EventLog" />

       </root> 

       <logger name="BizTalkSample">

              <level value="ALL" />

              <appender-ref ref="OutputDebugString"/>

       </logger> 

</log4net>