BizTalk Server Tutorial

BizTalk Server Concepts and Common Errors

ETW (Event Tracing for Windows) Logging – Part 1

As everyone know, Logging / Tracing is very important to solve most of the run time issues. Especially when you do production support and find that a particular transaction failed, without proper logs, it is very difficult to debug and resolve the issue.

There are many different ways of implementing logging and below is one approach of instrumenting your BizTalk Application (or any .NET application in general)

Basics about how ETW Logging works can be found by doing simple Google search. ETW is considered to be best in terms of performance and consumes less CPU. In this blog I wanted to show how ETW can be used to log critical debug information in a typical BizTalk Application.

Everyone who is interested in ETW logging for BizTalk would have seen this blog post. Although this is a starting point for me, I am not interested in relying on Microsoft.BizTalk.Tracing.dll and rather wanted to check for a generic approach for logging. Moreover I need pretty simple non fancy way of logging strings & errors message / stack traces.

 

Here is my requirement:
I am using BizTalk as a middleware Integration server. I receive a message, do some processing in custom pipeline component & give it to an orchestration & send it to a destination after some post processing (a typical BizTalk Application).

Rcv -> Custom Pipeline Component -> Orchestration -> Custom Pipeline Component -> Snd

For various messages that I receive, I want to log the details of the message processing in each of the stages. My trace logs should show something like below.

Message123: Entered Receive Pipeline Component
Message123: Some Processing information + metadata that I need for debugging / reprocessing in case of failures
Message123: Exited Receive Pipeline Component
Message123: Entered Orchestration
Message123: Some Processing information + metadata that I need for debugging / reprocessing in case of failures
Message123: Exited Orchestration
Message123: Entered Send Pipeline Component
Message123: Some Processing information + metadata that I need for debugging / reprocessing in case of failures
Message123: Exited Send Pipeline Component

I believe this is what any developer would like to see to instrument their application.

Solution:

In the past I worked with different clients in different domains. I implemented similar solution using BAM. However BAM should not be used for instrumenting the application. Moreover, we can’t use BAM to log exceptions or stack trace. Some clients wanted to store logging data in a custom database using Enterprise Library. Some rely on BizTalk management console & event log alone.
ETW is another way to do logging and performs well under load and very simple coding.

Before you proceed, check below.

• Try to understand how ETW Works
• .NET 3.5 and above provides EventProviderTraceListener class which writes events to ETW.
• You can add EventProviderTraceListener as a listener to the TraceSource object and use the standard TraceInformation method to write TraceLogs.
• In addition to .NET coding, you need to do some additional steps to actually start / stop & decode tracing.

Step 1: Create a Static Class containing Static TraceSource object for each BizTalk application. For example, if you have 2 BizTalk applications, create a Static Class like below. Make a note of the GUIDs for each application.

1

Step 2: Create another static class to write trace information messages & exception messages.

2

Step 3: Create a BizTalk application to test.

Receive -> Custom Pipeline Component –> Orchestration -> Custom Pipeline Component -> Send Port

3

Step 4: Add trace log statements in Custom Pipeline Component & Orchestration. I want to trace each message as it goes through Receive Pipeline, Orchestration & Send Pipeline. Since InterchangeId is same in all the stages, I want to use InterchangeId as TransactionId of the message.

Sample Pipeline Component with trace statements:

4

Sample Orchestration with Trace Statements:
5

varGuid = System.Guid.Parse(Message_1(BTS.InterchangeID));
ETWLogging.Utilities.Logger.TraceInformation(“Inside Orchestration”,ETWLogging.Utilities.Applications.Application_1,varGuid);

Step 5: Deploy and Test your application. Bind the orchestration’s logical ports to physical ports with File Adapters. Drop a file and see if you get the response. So far, BizTalk is raising Trace events to ETW. But they are not captured.

 

Step 6: Capturing the ETW Events.

• There are command line tools called “logman” and “tracerpt”. These come with Windows (Vista and above I guess).
• Logman can be used to start / stop capturing the ETW Events & writing them to a binary file.
• Tracerpt can be used to decode the binary file into XML or CSV file. Resultant file will have your logs.

Step 6a. Create ETW Data Collector.
Open command prompts as and give the following command

logman create trace Application_1 -o D:\TraceLogs\Application_1.etl -p “{5642612B-272D-4A85-BEC6-EAE8F6A4E978}” -a –v -ft 3

Application_1 -> Name of the application that we would like to capture the trace logs.
-o -> Output file name. This will have the logs in binary format.
-p -> GUID you used in Step 1 above
-a -> Always append to the same file instead of creating new files.
–v -> Do not use version for the file name
-ft -> Flush every 3 seconds.

Complete description of logman can be found here

6

Step 6b: Start capturing trace.
Run the command: logman start Application_1
After this command you should see a file created in the folder.
7

8

Step 6c: Now test run the BizTalk application by dropping some files. You will see that after every 3 seconds, the size of etl files keeps growing as it contains the logs generated by your BizTalk code.
Step 6d: Decode binary file and get logs in XML format
Use the command: tracerpt D:\TraceLogs\Application_1.etl -o D:\TraceLogs\Application_1_Logs.xml -of xml
Now you will have the actual log data.
Tracerpt supports several other options. Check it here

9.

10

Step 6e: If you want to stop capturing the logs, use the command logman stop Application_1. To delete the Data Collector use logman delete Application_1
Note: The decoded ETW logs will be in an XML format. You can use a TMF file to convert the xml file into a specific format you need. Or apply some XSLT or use notepad++ as shown in above screenshot.
More on this in next blog post.

– Shiv

May 15, 2014 - Posted by | Interesting Ones… Have a Look | , , , , ,

No comments yet.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: