Diagnostic Tracing with BizTalk 2004

(Note – this work has been updated for log4net 1.2.9. See the ‘Tools’ download in
the Deployment
Framework)

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:

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

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):

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).

This might yield trace output as follows:

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”.  (Update
– these are now currently found in the “Extra Tools” download for
the Deployment Framework – see the download links at the blog
home page.)

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.  (Update – the
  current version of this sample will now always be found in the Deployment Framework
  sample – see download links at the blog
  home page.)

• If you are using NAnt to deploy your BizTalk solution, extend your customDeployTarget
  as shown 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). (Handled for you in current rev
  of deployment framework.) Also, 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.  This step is NOT needed in current rev of Deployment Framework… -->
   <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.)&nbps;An alternative is to use scope-local logger variables
  that are initialized by assigning them to a global instance.

• 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:

(click)

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>