Exploring WCF Services
LANGUAGES: C#
TECHNOLOGIES: .NET 4.0 | WCF
Monitoring and Troubleshooting .NET 4 Services
Techniques for debugging traditional WCF Services and Workflow
Services built on .NET 4
By Zoiner Tejada
Debugging, troubleshooting, and monitoring are
procedures familiar to any developer; all revolve around finding the "right"
information. With .NET Framework 4.0, the number of options to find the right
information is expanding, but .NET 4 also continues support of some tried and
true techniques you may already be using. We'll explore the use of the Microsoft
Visual Studio Debugger, Event Tracing for Windows (ETW), and Windows
Application Server Extensions (code-named "Dublin") as valid tools to
help you troubleshoot both imperative .NET 4 Windows Communication Foundation (WCF)
services and declarative workflow services from development through production
deployment.
Visual Studio Debugger Enhancements
No tool is more familiar to the .NET developer than
Visual Studio, and when it comes to quickly smoking out a problem at
development time, Visual Studio's debugger is hard to beat. This continues to
hold true for debugging of traditional WCF and workflow services. In Visual
Studio 2010, the F5 experience depends on the project template chosen. When
pressing F5 to start a debug session with a WCF Service Library, the WCF
Service Host will spin up with the debugger attached, and the WCF Test Client
will be launched ready to make calls against the newly started service; this
behavior is unchanged from Visual Studio 2008.
For a Declarative Flowchart or Sequential Service
Library, the default is to launch and attach to an instance of WebDev.exe
(variously known as Cassini, the Visual Studio Web Development Server, or the
ASP.NET Development Server) with an automatically assigned port for each such
project in the solution. In solutions with multiple Declarative Service projects,
it is useful to set the Always Start When Debugging property to false when you're
interested only in hosting and debugging projects you've set as startup.
A Declarative Service project may be configured to
run within Microsoft IIS by choosing the project properties and clicking the
Web tab. Figure 1 shows the result of changing the Servers selection to Use
Local IIS Web Server and pressing the Create Virtual Directory button.
Figure 1: Configuring a project to run under IIS
Once configured this way, the debugger will attach
to the worker process responsible for that virtual directory. Manually attaching
to the process hosting either type of service is another option, which you activate
via the Debug, Attach to Process menu. In the case of a declarative workflow service,
to enable graphical debugging of your workflow (discussed shortly), you must explicitly
attach to Workflow code by unchecking Managed (v4.0) and checking Workflow in
the Select Code Type dialog box that appears when you press Select in the
Attach to Process dialog box.
Once debugger is attached to the hosting process,
debugging imperative WCF service code is just like debugging other managed
code. However, if you're attached to a declarative workflow service, you can
take advantage of graphical debugging, which lets you step into and across
activities as if they were lines of code. Here you can also toggle breakpoints
on activities in the workflow diagram, as Figure 2 shows. Upon hitting one, you
can examine workflow variable values in the Locals, Watch, or Immediate windows.
Figure 2: Hitting a breakpoint during graphical debugging of a workflow
While stopped at a breakpoint, you can also view
the Call Stack, which will list the executing activities by name in the unique
dotted form:
Workflow![Dotted Path To Executing Activity] .[ExecutingActivityDisplayName]()
This is followed by a line number referring to the
activity's line number in the XAMLX; Figure 3 shows an example call stack. It's
worth noting that by opening the XAMLX using the XML editor when the code is stopped
at a breakpoint, the line of XAML source will be highlighted to display the
current statement (yellow) and breakpoints (red).
Figure 3: A workflow service call stack
Introducing Event Tracing for Windows
If you open the Event Viewer on Windows Vista or
later, you'll find a new set of logs called Application and Service logs in
addition to the System, Security, and Application Windows Event logs. The goal
of Application and Service logs is to store diagnostic events for a particular
application or component instead of events that are more global in their scope
(e.g., events written to the System log). These logs are populated by a new,
high-performance infrastructure, ETW. There are four event sources:
Workflow Tracking: provides events that describe
workflow lifecycle events, activity state changes, variable values, exceptions,
and user-defined events.
WCF Analytic Trace: provides events that include
service host details, message processing, operation invocation, and faults.
WCF Message Logging: provides events that
capture the contents of service messages.
WCF Diagnostic Trace: provides both WCF trace
and message log events.
.NET 4 unifies the logging of Workflow Tracking
Records, WCF Analytic Trace Events, and WCF Message Logs by writing those
events to a new set of Application and Service logs via ETW. WCF Diagnostic
Trace refers to the trace and message events that are logged to .svclog files
on the file system, as was possible in .NET 3.5 and is still supported in .NET
4.
Viewing ETW Events
The querying and analysis of ETW events for
imperative WCF Services and declarative workflow services is a simple matter of
opening the Event Viewer and navigating to the appropriate log underneath the
Application and Service Logs\Microsoft\WCF\WF-Development tree. Windows defines
the following four standard log subtypes:
Admin: logs events that define a problem and
provide the corrective action that an administrator should take.
Analytic: logs events that detail application
execution in high volume and are useful variously for troubleshooting and monitoring.
Debug: logs issues of interest to a developer
only while troubleshooting.
Operational: logs events of value to an end user
or administrator that relate to an application as it is running, though they
may not provide specific actionable guidance.
Of these four subtypes, the two most useful for
troubleshooting .NET Services are the Analytic and Debug logs. The Analytic log,
which Figure 4 shows, is the log for viewing the vast majority of useful events
including workflow activity, user-created tracking records, service operation
traces, and message logs. The Debug log is mostly used like a meta log: It
records events about other events that could not be properly logged in the
Analytic log for example, noting events that were not logged or were truncated.
It is also where verbose events from the .NET Services infrastructure are
logged.
Figure 4: Viewing tracking records in the Analytic log
A distinct advantage resulting from ETW's unified
logging is the ability to easily see the correlated, ordered sequence of events
between WCF activity and workflow execution. For example, the table in Figure 5 shows a new instance of the workflow we debugged in Figure 2 being launched as
the result of invoking a workflow service's Receive activity (with
CanCreateInstance set to true), defining the GetData operation, which takes an
integer.
The events logged within the Analytic log fall
broadly into two source categories according to their EventID:
100 199 represent workflow tracking records.
200 and greater represent WCF trace and message
log records.
When performing analysis of the events in the Event
Viewer, you might find it useful to filter out, for example, just the workflow
tracking records. To create a custom view on records captured in the Analytic
log, follow these steps:
1. Right-click
the Analytic log in the debug view and select Create Custom View.
2. In
the Includes/Excludes Event ID's text box, enter the range of IDs you want to
see. To filter for Workflow events only and exclude WCF traces, enter 100-199.
Click OK.
3. Give
the Custom View a name and click OK. Doing so will create the custom view under
the Custom Views folder in the Event Viewer. Clicking the custom view will show
the filtered event list.
Configuring ETW
To be able to view WF Tracking Record, WCF Analytic
Traces, and WCF Message Log Traces for imperative WCF or declarative workflow
services in the Event Viewer, you need to perform the following few steps:
1.
Show the Analytic/Debug logs: In Event Viewer,
right-click the WF-Development folder and choose View, Show Analytic and Debug logs.
2.
Enable the Analytic/Debug logs: In Event Viewer,
right-click the Analytic or Debug log you want to start collecting data and
choose Enable Log.
3.
Enable WF Tracking Events in service web.config:
Configure your Workflow Service to use the ETW Tracking Participant and
configure the volume of records tracked by defining a Tracking Profile for it. (This
setting does not apply to imperative WCF services.)
4.
Enable WCF Message Log Tracing in service
web.config: Add a messageLogging element to the system.serviceModel/diagnostics
section that enables message logging at the service and/or transport level.
Note that WCF Analytic traces are enabled by default.
Figure 6 shows a sample web.config that registers
the ETW tracking participant with the service via its service behavior,
configures the ETW tracking participant with the JustRightTrackingProfile
tracking profile defined further down, and defines a messageLogging element
that enables the logging of complete messages at the service and transport
level.
Tracking profiles, such as the one shown in Figure 6,
define zero or more queries for each of the 10 different kinds of tracking
records that the workflow runtime is capable of emitting. A record is only sent
to the tracking participant when it matches one of the defined queries. The
specifics of configuring each of the 10 query elements are beyond the scope of
this article. Just as in WCF we can log the message body by enabling message
logging, tracking profiles also let us log the values of workflow variables for
activity events that match a defined query. For example, in the simple workflow
we traced previously, we could capture the value of the "data"
variable it defines by adding the following activity query as a child of the
existing activityQueries element:
<activityQuery activityName="ReceiveRequest">
<variableQueries>
<variableQuery name="afterGetData"
variable="data" isRequired="false"/>
</variableQueries>
<states>
<state name="Closed"/>
</states>
</activityQuery>
This would result in the last record listed in
Figure 5 changing to include the value of the "data" variable
extracted when the ReceiveRequest activity completed its execution, as Figure 7 shows.
Limitations of ETW Trace Events
The maximum size of a serialized ETW record cannot
exceed 64KB. When a record exceeds this size, a warning-level trace record will
be written to the Debug log, informing of either truncation or a failure to log
the record. Special cases of this occur when caused by large variable payloads
or message log content. In the former, the variable element will be truncated
and have its content replaced with ellipses; in the latter, the message won't
be logged. If you require the value of a message log, but it's always exceeding
the ETW buffer size, then you must fall back to the .NET 3.5 approach of using
WCF Diagnostic Message Logging and enable writing the message logs to .svclog
files.
Application Server Extensions (aka "Dublin")
Dublin is a free, feature-rich enhancement to IIS. Although
ETW provides a lot of information, the Event Viewer is limited in its ability
to present the trace events in a fashion that's easy is to query (basically you
can query only by timestamp and EventID) and navigate (solely moving between
the Debug/Analytic log, through paged sets of events). Among many features that
enhance service configuration and server robustness, Dublin adds a rich UI to
the IIS Management Console that enables drill-down from a high-level dashboard
(Figure 8) into WCF service calls or instances of a service and further into
tracked events for that service. Moreover, it provides querying capabilities on
event trace details, such as querying by variable values (Figure 9), which
enable you to locate a service instance from the single event record that had
the requested variable value (simply by right-clicking the returned event
record and selecting Tracked Service Instance).
Figure 8: Dublin monitoring dashboard
Figure 9: Configuring a query to return events containing the variable afterGetData with the value 42
Under the covers, Dublin creates a trace session
with ETW and logs the trace records it receives from the WF Tracking, WCF
Analytic Trace, and WCF Message Logging providers to its monitoring SQL Server database.
This has two ramifications. By storing the event records in a SQL Server database
that's designed to be externally available (it even provides views to simplify
querying the database directly), Dublin enables queries and analysis that might
not be possible through the UI. The fact that it is logging ETW traces does
cause one issue that may surprise you. Even though records are being logged to
a SQL Server database that could support large event payloads, the 64KB event
size limit still applies, and truncation or dropped events will still occur
when they exceed this limit.
Configuring Dublin Monitoring
Out of the box, Dublin is pretty much ready to go.
In the latest Community Technology Preview (CTP), you configure monitoring by
selecting the server node (future releases will provide full support for
configuring at the application level), right-clicking, selecting Configure defaults, then selecting
Monitoring from the left tabs, as Figure 10 shows. The dialog box that's presented
is effectively helping you edit the web.config relevant to the scope you've selected.
In this case, that would mean changes made here will be reflected in the root
web.config located under C:[WinDir]\Microsoft.NET\Framework\v4.0.20506\config.
Figure 10: Dublin monitoring configuration
By default Dublin is set to use a monitoring level
of Health Monitoring, which among other things automatically configures the tracking
profile for the workflow service to use the HealthMonitoring_Tracking_Profile.
The profile will collect only workflow instance-level events, unhandled
exceptions, faults, and correlation events; it will not collect activity-level
events. Changing this to include activity events is a simple matter of raising
the Level slider to Troubleshooting and clicking Apply. Doing so will change the
tracking profile used by the ETW tracking participant to one that also includes
activity state-change events, activity scheduling, canceling, bookmark
resumptions, and all custom user tracking events. As an aside, these default
profiles are defined in machine.config.
If you want to enable variable value extraction, you'll
have to define your own tracking profile and register it with Dublin. Simply
click the Configure button on the Monitoring pane, click Add new, and browse to the Tracking Profile (*.tp) file containing
the tracking profile you want to use. A tracking profile file is simply the
same trackingProfile element you'd use in a web.config (like the
JustRightDebugProfile we defined in Figure 6 previously), extracted to a text
file with the .tp extension. Once you've selected the file, give the profile a
name, and check the box to Set as current
active tracking profile, then click OK three times.
Also note that Dublin enables you to configure WCF
Diagnostic traces (which write to files independent from the Dublin monitoring
database) from the same Monitoring configuration screen.
More Options for Services Troubleshooting
Because setting up your service to run in Dublin
can be as simple as changing the project properties from running under the
ASP.NET Development Server to running under IIS, it makes a lot of sense to use
Dublin's powerful monitoring tools from the beginning of any services
development project. The functionality provided by Dublin naturally carries
forward to test and production with the appropriate configuration changes to
adjust the volume of logged data. The one place where you cannot use Dublin for
monitoring is in the scenario where your ServiceHost or WorkflowServiceHost are
self hosted in their own process. Here you must use ETW or the Visual Studio
Debugger.
Zoiner Tejada (ztejada@hersheytech.com) is
passionate about workflow and the future of implementing connected systems with
them. He's the chief software architect at Hershey Technologies, is recognized
as a Microsoft Industry Influencer, and is an advisor to Microsoft's Connected
Systems Division. Zoiner has a degree in computer science from Stanford
University and blogs at TheWorkflowElement.com.
Figure 5:
Sample ETW log content
|
Event ID
|
Value in
General Tab
|
|
215
|
The transport has received a message at a listen URI
'http://localhost/ServiceLibrary1/Service1.xamlx/Contract1'.
|
|
451
|
<MessageLogTraceRecord>
<HttpRequest>
<Method>POST</Method>
<QueryString></QueryString>
<WebHeaders>
<Connection>Keep-Alive</Connection>
<Content-Length>167</Content-Length>
<Content-Type>text/xml;
charset=utf-8</Content-Type>
<Expect>100-continue</Expect>
<Host>hostName</Host>
<SOAPAction>"http://tempuri.org/Contract1/GetData"</SOAPAction>
</WebHeaders>
</HttpRequest>
<Envelope>
<Header>
<To>http://hostName/ServiceLibrary1/Service1.xamlx/Contract1</To>
<Action>http://tempuri.org/Contract1/GetData</Action>
</Header>
<Body>
<int>42</int>
</Body>
</Envelope>
</MessageLogTraceRecord>
|
|
205
|
The operation 'GetData' of an instance of:
'a2983685-5516-401f-9d6c-cbc5025d18a3' invoked.
|
|
100
|
TrackRecord= WorkflowInstanceRecord,
InstanceID =
{a2983685-5516-401f-9d6c-cbc5025d18a3}, RecordNumber = 0, EventTime =
2009-08-02T13:25:12.287109300Z, Level =
Info, State = Started, Annotations
= <Annotations></Annotations>, ProfileName =
JustRightDebugProfile
|
|
104
|
TrackRecord =
ActivityScheduledRecord, InstanceID =
{a2983685-5516-401f-9d6c-cbc5025d18a3},
RecordNumber = 1, EventTime
= 2009-08-02T13:25:12.287109300Z, Level =
Info, Name = , ActivityId = , ActivityInstanceId = , ChildActivityName =
Sequential Service, ChildActivityId = 1, ChildActivityInstanceId = 1,
Variables=<Variables></Variables>,
Annotations=<Annotations></Annotations>, ProfileName =
JustRightDebugProfile
|
|
104
|
TrackRecord =
ActivityScheduledRecord, InstanceID =
{a2983685-5516-401f-9d6c-cbc5025d18a3},
RecordNumber = 2, EventTime
= 2009-08-02T13:25:12.287109300Z, Level =
Info, Name = Sequential Service, ActivityId = 1, ActivityInstanceId = 1, ChildActivityName
= ReceiveRequest, ChildActivityId = 2, ChildActivityInstanceId = 2,
Variables=<Variables></Variables>,
Annotations=<Annotations></Annotations>, ProfileName =
JustRightDebugProfile
|
|
|
additional records elided for clarity
|
|
103
|
TrackRecord =
ActivityTrackingRecord, InstanceID =
{a2983685-5516-401f-9d6c-cbc5025d18a3}, RecordNumber=11,
EventTime=2009-08-02T13:25:12.290039000Z,
Level = Info, State = Closed, Name=ReceiveRequest, ActivityId=2,
ActivityInstanceId=2, Variables=<Variables></Variables>,
Annotations=<Annotations></Annotations>, ProfileName =
JustRightDebugProfile
|
Figure 6:
Sample web.config that enables ETW tracing
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<!--... other sections
elided ...-->
<system.serviceModel>
<services>
<service name="Service1"
behaviorConfiguration="DeclarativeSequentialServiceLibrary1.Service1Behavior"
>
</service>
</services>
<behaviors>
<serviceBehaviors>
<behavior
name="DeclarativeSequentialServiceLibrary1.Service1Behavior">
<!--... other
behaviors ...-->
<trackingComponents>
<add
name="EtwTrackingParticipant" />
</trackingComponents>
</behavior>
</serviceBehaviors>
</behaviors>
<diagnostics>
<messageLogging
logEntireMessage="true" logKnownPii="true"
logMalformedMessages="true"
logMessagesAtServiceLevel="true"
logMessagesAtTransportLevel="false" />
</diagnostics>
<tracking>
<participants>
<add
name="EtwTrackingParticipant"
type="System.Activities.Tracking.EtwTrackingParticipant, System.Activities,
Version=4.0.0.0,
Culture=neutral, PublicKeyToken=31bf3856ad364e35"
profileName="JustRightDebugProfile"
/>
</participants>
<profiles>
<trackingProfile
name="JustRightDebugProfile">
<workflow>
<activityScheduledQueries>
<activityScheduledQuery activityName="*"
childActivityName="*"/>
</activityScheduledQueries>
<activityQueries>
<activityQuery activityName="*">
<states>
<state
name="Closed"/>
</states>
</activityQuery>
</activityQueries>
<cancelRequestedQueries>
<cancelRequestedQuery activityName="*"
childActivityName="*"/>
</cancelRequestedQueries>
<faultPropagationQueries>
<faultPropagationQuery activityName="*"
extractFaultData="true" faultHandlerActivityName="*"/>
</faultPropagationQueries>
<workflowInstanceQuery>
<states>
<state
name="*"/>
</states>
</workflowInstanceQuery>
<workflowInstanceAbortedQuery
includeReasonAborted="true"/>
<workflowInstanceUnhandledExceptionQuery
includeException="true"/>
</workflow>
</trackingProfile>
</profiles>
</tracking>
</system.serviceModel>
</configuration>
Figure 7:
Section of trace showing value of the "data" variable
|
103
|
TrackRecord
= ActivityTrackingRecord, InstanceID =
{11710778-2020-4b64-b46f-da39fa81bbdb}, RecordNumber=11, EventTime=2009-08-02T15:16:05.935546800Z,
Level = Info, State = Closed, Name=ReceiveRequest, ActivityId=2,
ActivityInstanceId=2, Variables=<Variables><item
name="afterGetData" type="System.Int32"
value="42"/></Variables>,
Annotations=<Annotations></Annotations>, ProfileName =
JustRightDebugProfile
|