Monitoring and Troubleshooting .NET 4 Service

Exploring WCF Services

LANGUAGES: C#

TECHNOLOGIES: .NET 4.0 | WCF

Monitoring and Troubleshooting .NET 4 Services

Techniques for debugging traditional WCF Services and WorkflowServices built on .NET 4

By Zoiner Tejada

Debugging, troubleshooting, and monitoring areprocedures familiar to any developer; all revolve around finding the "right"information. With .NET Framework 4.0, the number of options to find the rightinformation is expanding, but .NET 4 also continues support of some tried andtrue techniques you may already be using. We'll explore the use of the MicrosoftVisual Studio Debugger, Event Tracing for Windows (ETW), and WindowsApplication Server Extensions (code-named "Dublin") as valid tools tohelp you troubleshoot both imperative .NET 4 Windows Communication Foundation (WCF)services and declarative workflow services from development through productiondeployment.

Visual Studio Debugger Enhancements

No tool is more familiar to the .NET developer thanVisual Studio, and when it comes to quickly smoking out a problem atdevelopment time, Visual Studio's debugger is hard to beat. This continues tohold true for debugging of traditional WCF and workflow services. In VisualStudio 2010, the F5 experience depends on the project template chosen. Whenpressing F5 to start a debug session with a WCF Service Library, the WCFService Host will spin up with the debugger attached, and the WCF Test Clientwill be launched ready to make calls against the newly started service; thisbehavior is unchanged from Visual Studio 2008.

For a Declarative Flowchart or Sequential ServiceLibrary, the default is to launch and attach to an instance of WebDev.exe(variously known as Cassini, the Visual Studio Web Development Server, or theASP.NET Development Server) with an automatically assigned port for each suchproject 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'reinterested only in hosting and debugging projects you've set as startup.

A Declarative Service project may be configured torun within Microsoft IIS by choosing the project properties and clicking theWeb tab. Figure 1 shows the result of changing the Servers selection to UseLocal 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 attachto the worker process responsible for that virtual directory. Manually attachingto the process hosting either type of service is another option, which you activatevia 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 explicitlyattach to Workflow code by unchecking Managed (v4.0) and checking Workflow inthe Select Code Type dialog box that appears when you press Select in theAttach to Process dialog box.

Once debugger is attached to the hosting process,debugging imperative WCF service code is just like debugging other managedcode. However, if you're attached to a declarative workflow service, you cantake advantage of graphical debugging, which lets you step into and acrossactivities as if they were lines of code. Here you can also toggle breakpointson activities in the workflow diagram, as Figure 2 shows. Upon hitting one, youcan 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 viewthe Call Stack, which will list the executing activities by name in the uniquedotted form:

Workflow![Dotted Path To Executing Activity] .[ExecutingActivityDisplayName]()

This is followed by a line number referring to theactivity's line number in the XAMLX; Figure 3 shows an example call stack. It'sworth noting that by opening the XAMLX using the XML editor when the code is stoppedat a breakpoint, the line of XAML source will be highlighted to display thecurrent 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 orlater, you'll find a new set of logs called Application and Service logs inaddition to the System, Security, and Application Windows Event logs. The goalof Application and Service logs is to store diagnostic events for a particularapplication 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 describeworkflow lifecycle events, activity state changes, variable values, exceptions,and user-defined events.

        WCF Analytic Trace: provides events that includeservice host details, message processing, operation invocation, and faults.

        WCF Message Logging: provides events thatcapture the contents of service messages.

        WCF Diagnostic Trace: provides both WCF traceand message log events.

.NET 4 unifies the logging of Workflow TrackingRecords, WCF Analytic Trace Events, and WCF Message Logs by writing thoseevents to a new set of Application and Service logs via ETW. WCF DiagnosticTrace refers to the trace and message events that are logged to .svclog fileson the file system, as was possible in .NET 3.5 and is still supported in .NET4.

Viewing ETW Events

The querying and analysis of ETW events forimperative WCF Services and declarative workflow services is a simple matter ofopening the Event Viewer and navigating to the appropriate log underneath theApplication and Service LogsMicrosoftWCFWF-Development tree. Windows definesthe following four standard log subtypes:

        Admin: logs events that define a problem andprovide the corrective action that an administrator should take.

        Analytic: logs events that detail applicationexecution in high volume and are useful variously for troubleshooting and monitoring.

        Debug: logs issues of interest to a developeronly while troubleshooting.

        Operational: logs events of value to an end useror administrator that relate to an application as it is running, though theymay not provide specific actionable guidance.

Of these four subtypes, the two most useful fortroubleshooting .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 eventsincluding workflow activity, user-created tracking records, service operationtraces, and message logs. The Debug log is mostly used like a meta log: Itrecords events about other events that could not be properly logged in theAnalytic log for example, noting events that were not logged or were truncated.It is also where verbose events from the .NET Services infrastructure arelogged.

Figure 4: Viewing tracking records in the Analytic log

A distinct advantage resulting from ETW's unifiedlogging is the ability to easily see the correlated, ordered sequence of eventsbetween 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 asthe result of invoking a workflow service's Receive activity (withCanCreateInstance set to true), defining the GetData operation, which takes aninteger.

The events logged within the Analytic log fallbroadly into two source categories according to their EventID:

        100 199 represent workflow tracking records.

        200 and greater represent WCF trace and messagelog records.

When performing analysis of the events in the EventViewer, you might find it useful to filter out, for example, just the workflowtracking records. To create a custom view on records captured in the Analyticlog, follow these steps:

1.     Right-clickthe Analytic log in the debug view and select Create Custom View.

2.     Inthe Includes/Excludes Event ID's text box, enter the range of IDs you want tosee. To filter for Workflow events only and exclude WCF traces, enter 100-199.Click OK.

3.     Givethe Custom View a name and click OK. Doing so will create the custom view underthe Custom Views folder in the Event Viewer. Clicking the custom view will showthe filtered event list.

Configuring ETW

To be able to view WF Tracking Record, WCF AnalyticTraces, and WCF Message Log Traces for imperative WCF or declarative workflowservices 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 andchoose Enable Log.

3.    Enable WF Tracking Events in service web.config:Configure your Workflow Service to use the ETW Tracking Participant andconfigure the volume of records tracked by defining a Tracking Profile for it. (Thissetting does not apply to imperative WCF services.)

4.    Enable WCF Message Log Tracing in serviceweb.config: Add a messageLogging element to the system.serviceModel/diagnosticssection 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 registersthe ETW tracking participant with the service via its service behavior,configures the ETW tracking participant with the JustRightTrackingProfiletracking profile defined further down, and defines a messageLogging elementthat enables the logging of complete messages at the service and transportlevel.

Tracking profiles, such as the one shown in Figure 6,define zero or more queries for each of the 10 different kinds of trackingrecords that the workflow runtime is capable of emitting. A record is only sentto the tracking participant when it matches one of the defined queries. Thespecifics of configuring each of the 10 query elements are beyond the scope ofthis article. Just as in WCF we can log the message body by enabling messagelogging, tracking profiles also let us log the values of workflow variables foractivity events that match a defined query. For example, in the simple workflowwe traced previously, we could capture the value of the "data"variable it defines by adding the following activity query as a child of theexisting activityQueries element:

This would result in the last record listed inFigure 5 changing to include the value of the "data" variableextracted when the ReceiveRequest activity completed its execution, as Figure 7 shows.

Limitations of ETW Trace Events

The maximum size of a serialized ETW record cannotexceed 64KB. When a record exceeds this size, a warning-level trace record willbe written to the Debug log, informing of either truncation or a failure to logthe record. Special cases of this occur when caused by large variable payloadsor message log content. In the former, the variable element will be truncatedand have its content replaced with ellipses; in the latter, the message won'tbe logged. If you require the value of a message log, but it's always exceedingthe ETW buffer size, then you must fall back to the .NET 3.5 approach of usingWCF Diagnostic Message Logging and enable writing the message logs to .svclogfiles.

Application Server Extensions (aka "Dublin")

Dublin is a free, feature-rich enhancement to IIS. AlthoughETW provides a lot of information, the Event Viewer is limited in its abilityto present the trace events in a fashion that's easy is to query (basically youcan query only by timestamp and EventID) and navigate (solely moving betweenthe Debug/Analytic log, through paged sets of events). Among many features thatenhance service configuration and server robustness, Dublin adds a rich UI tothe 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 intotracked events for that service. Moreover, it provides querying capabilities onevent trace details, such as querying by variable values (Figure 9), whichenable you to locate a service instance from the single event record that hadthe requested variable value (simply by right-clicking the returned eventrecord 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 sessionwith ETW and logs the trace records it receives from the WF Tracking, WCFAnalytic 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 databasethat's designed to be externally available (it even provides views to simplifyquerying the database directly), Dublin enables queries and analysis that mightnot be possible through the UI. The fact that it is logging ETW traces doescause one issue that may surprise you. Even though records are being logged toa SQL Server database that could support large event payloads, the 64KB eventsize limit still applies, and truncation or dropped events will still occurwhen 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 byselecting the server node (future releases will provide full support forconfiguring at the application level), right-clicking, selecting Configure defaults, then selectingMonitoring from the left tabs, as Figure 10 shows. The dialog box that's presentedis 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 rootweb.config located under C:[WinDir]Microsoft.NETFrameworkv4.0.20506config.

Figure 10: Dublin monitoring configuration

By default Dublin is set to use a monitoring levelof Health Monitoring, which among other things automatically configures the trackingprofile for the workflow service to use the HealthMonitoring_Tracking_Profile.The profile will collect only workflow instance-level events, unhandledexceptions, faults, and correlation events; it will not collect activity-levelevents. Changing this to include activity events is a simple matter of raisingthe Level slider to Troubleshooting and clicking Apply. Doing so will change thetracking profile used by the ETW tracking participant to one that also includesactivity state-change events, activity scheduling, canceling, bookmarkresumptions, and all custom user tracking events. As an aside, these defaultprofiles are defined in machine.config.

If you want to enable variable value extraction, you'llhave to define your own tracking profile and register it with Dublin. Simplyclick the Configure button on the Monitoring pane, click Add new, and browse to the Tracking Profile (*.tp) file containingthe tracking profile you want to use. A tracking profile file is simply thesame trackingProfile element you'd use in a web.config (like theJustRightDebugProfile we defined in Figure 6 previously), extracted to a textfile with the .tp extension. Once you've selected the file, give the profile aname, and check the box to Set as currentactive tracking profile, then click OK three times.

Also note that Dublin enables you to configure WCFDiagnostic traces (which write to files independent from the Dublin monitoringdatabase) from the same Monitoring configuration screen.

More Options for Services Troubleshooting

Because setting up your service to run in Dublincan be as simple as changing the project properties from running under theASP.NET Development Server to running under IIS, it makes a lot of sense to useDublin's powerful monitoring tools from the beginning of any servicesdevelopment project. The functionality provided by Dublin naturally carriesforward to test and production with the appropriate configuration changes toadjust the volume of logged data. The one place where you cannot use Dublin formonitoring is in the scenario where your ServiceHost or WorkflowServiceHost areself hosted in their own process. Here you must use ETW or the Visual StudioDebugger.

Zoiner Tejada ([email protected]) ispassionate about workflow and the future of implementing connected systems withthem. He's the chief software architect at Hershey Technologies, is recognizedas a Microsoft Industry Influencer, and is an advisor to Microsoft's ConnectedSystems Division. Zoiner has a degree in computer science from StanfordUniversity and blogs at TheWorkflowElement.com.

Figure 5:Sample ETW log content

Figure 6:Sample web.config that enables ETW tracing

behaviorConfiguration="DeclarativeSequentialServiceLibrary1.Service1Behavior"> logMessagesAtServiceLevel="true"logMessagesAtTransportLevel="false" /> type="System.Activities.Tracking.EtwTrackingParticipant, System.Activities,Version=4.0.0.0,Culture=neutral, PublicKeyToken=31bf3856ad364e35" profileName="JustRightDebugProfile" /> 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=, Annotations=, ProfileName = JustRightDebugProfile