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.
Appenders: An output destination for logging.
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:
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> |