Debugging Web Services Under Load
Sometimes, bugs only show up when the Web Service is serving a large number of requests. Setting breakpoints may not help if the behavior does not show up when things are slowed down (and nothing slows a service more than a breakpoint). To handle this, you enter the unhappy world of reviewing trace data. Because breakdown under load happens quite frequently, I recommend that you audit every entry point into the Web Service itself. By storing that information, the person analyzing the failure can recreate an accurate picture of what was happening at the time of the failure. This section will cover the things you should store at all times so that you can analyze where your code failed. As a developer, you will want to use this in conjunction with trace levels and such. The trace classes are typically covered quite well in introductory texts. If you do not have a basic reference, I would recommend that you purchase one very soon.
When auditing this information, do not place it in a file. As the file grows, and it will grow quickly under load, you will see file writes take longer and longer. Instead, consider logging your audit data to a database. Simple database inserts typically take very little time. As an added bonus, the database operations probably will not slow down as the amount of information grows. You may wind up making a large number of calls to figure out exactly what is going wrong. Decide what data you need to collect (each case will be different) and store it. A stored procedure may get you the best performance and impact the overall application the least.
For practical purposes, you might want to build this apparatus ahead of time, just to audit Web Service activity. When bugs start popping up, you can add extra lines of code to insert extra audit records. Some data items you may want to record are as follow:
Method identifier. This can be a numeric value or a string.
Date and time the audit record was created by the Web Service.
Bit of data indicating whether the audit record represents success, failure due to server problems, failure due to client problems, or none of the above.
User-defined string specific to the audit record. This can contain extra data useful in debugging or to give the audit record extra meaning.
Additionally, you will want to define a record key. A numeric index will work well. Because auditing should happen in the background, a form of delayed writes works very well. Either execute the recording of the audit record in a low priority asynchronous process or put the audit record in a queue to be stored in the database later. Writes to a message queue are often faster than a database insert.
Believe it or not, building an auditing mechanism is one of the best proactive things you can do. Discuss this with your database administrator (DBA) and figure out how often you want to archive the audit data. Your DBA may want to have the audit records exist in a separate database to make archiving easy. Regardless, you will see benefits from implementing auditing before problems happen.
Because auditing is so important, let's take a look at an example—a custom SOAP attribute that will log method calls in a synchronous manner. This attribute does not handle the asynchronous logging previously recommended. It does do the basic logging, though. To use the class, you need to have a SQL Server database installed. The SQL isn't too complex. This includes the Microsoft Data Engine (MSDE), a freely distributable database bundled with many applications. You can get MSDE at http://msdn.microsoft.com/vstudio/msde/msde.asp.
This code will work on any existing database that has a table named Audit and a stored procedure named AddAudit. The SQL to create the table and stored procedure is shown in Listing 5.2. The sql file, auditData.sql, contains some extra code that handles removing the table and procedure if they already exist.
Listing 5.2. SQL to Create the Audit Table and AddAudit Stored Procedure
-- Create the Audit table
CREATE TABLE [dbo].[Audit] (
[ID] [int] IDENTITY (1, 1) NOT NULL ,
[startDate] [datetime] NOT NULL ,
[endDate] [datetime] NOT NULL ,
[result] [int] NOT NULL ,
[methodName] [nvarchar] (100) NOT NULL ,
[otherData] [nvarchar] (500) NULL
) ON [PRIMARY]
GO
ALTER TABLE [dbo].[Audit] WITH NOCHECK ADD
CONSTRAINT [PK_Audit] PRIMARY KEY CLUSTERED
(
[ID]
) ON [PRIMARY]
GO
-- Create the AddAudit stored procedure
CREATE PROCEDURE AddAudit
@startDate as DATETIME,
@endDate as DATETIME,
@result as INT,
@methodName as NVARCHAR(100),
@otherData as NVARCHAR(500)
AS
INSERT INTO Audit (startDate,
endDate,
result,
methodName,
otherData)
VALUES ( @startDate,
@endDate,
@result,
@methodName,
@otherData)
GO
|
After the database has been set up, you will need a way to tell any code how to open a connection to the database. The web.config file for any Web Service using the custom attribute about to be shown must contain the database connection string in the appSettings section of the configuration file. The name of the value must be AuditDB. Listing 5.3 shows a sample version of this section. The connection string points to the Northwind database that is installed by default with SQL Server.
Listing 5.3. Setting the AuditDB Value in the web.config File
<appSettings>
<add key="AuditDB" value=
"user id=sa;password=dbpassword;initial catalog=northwind;data
|
source=localhost;Connect_Timeout=30"/>
</appSettings>
How is this used? To answer that, we need to look at the first of three classes used to audit the Web Service. The AuditEntry class is used to store our audit data and then save it to a database when the complete round trip (request and response) is all but done. The class contains some simple properties as well as a Save method that writes the properties to the database. This class assumes that users have already executed the SQL in Listing 5.2 and added the value to the web.config file as shown in Listing 5.3. Listing 5.4 shows the complete listing for this class.
Listing 5.4. The AuditEntry Class
Imports System.Reflection
Imports System
Namespace com.scottseely
Public Enum CallResult
ServerFailure = 1
ClientFailure = 2
Success = 10
End Enum
Public Class AuditEntry
Private m_methodName As String
Private m_startTime As DateTime
Private m_endTime As DateTime
Private m_callResult As callResult
Private m_otherData As String = ""
' Stores the name of the method being audited
Public Property methodName() As String
Get
Return m_methodName
End Get
Set(ByVal Value As String)
m_methodName = Value
End Set
End Property
' Stores the time that the audit began
Public Property startTime() As DateTime
Get
Return m_startTime
End Get
Set(ByVal Value As DateTime)
m_startTime = Value
End Set
End Property
' Stores the time that the audit finished
Public Property endTime() As DateTime
Get
Return m_endTime
End Get
Set(ByVal Value As DateTime)
m_endTime = Value
End Set
End Property
' Stores the result of the SOAP method
Public Property callResult() As callResult
Get
Return m_callResult
End Get
Set(ByVal Value As callResult)
m_callResult = Value
End Set
End Property
' Stores any other data related to the method call
Public Property otherData() As String
Get
Return m_otherData
End Get
Set(ByVal Value As String)
m_otherData = Value
End Set
End Property
' Saves the audit information to a database
Public Sub Save()
Try
' Get the connection string from the
' application using this library
Dim connStr As String = _
System.Configuration.ConfigurationSettings. _
AppSettings.Item("AuditDB")
Dim conn As New SqlClient.SqlConnection(connStr)
conn.Open()
Dim comm As New SqlClient.SqlCommand()
'Setup the command object
comm.Connection = conn
comm.CommandType = CommandType.StoredProcedure
comm.CommandText = "AddAudit"
Dim startDateParam As New SqlClient.SqlParameter( _
"@startDate", SqlDbType.DateTime)
Dim endDateParam As New SqlClient.SqlParameter( _
"@endDate", SqlDbType.DateTime)
Dim resultParam As New SqlClient.SqlParameter( _
"@result", SqlDbType.Int)
Dim methodNameParam As New SqlClient.SqlParameter( _
"@methodName", SqlDbType.NVarChar, 100)
Dim otherDataParam As New SqlClient.SqlParameter( _
"@otherData", SqlDbType.NVarChar, 500)
startDateParam.Value = m_startTime
endDateParam.Value = m_endTime
resultParam.Value = m_callResult
methodNameParam.Value = m_methodName
otherDataParam.Value = m_otherData
' Add the parameters to the command object.
comm.Parameters.Add(startDateParam)
comm.Parameters.Add(endDateParam)
comm.Parameters.Add(resultParam)
comm.Parameters.Add(methodNameParam)
comm.Parameters.Add(otherDataParam)
' Execute the query. No results come back.
comm.ExecuteNonQuery()
' Clean up
conn.Close()
Catch ex As Exception
Trace.WriteLine(ex.ToString())
' This code will throw an exception of its own
' if the default Web user does not have permission
' to write to a log file.
Dim log As New System.Diagnostics.EventLog( _
"AuditLog", ".", "AuditLogError")
log.WriteEntry( _
"An exception was caught at " & _
DateTime.Now.ToString() & vbCrLf & _
"Exception details: " & ex.ToString())
log.Dispose()
End Try
End Sub
End Class
End Namespace
|
You will notice that the class is in its own namespace. I did this to help prevent name collisions with other classes. This code might get modified and reused quite a bit. If you modify this code, make sure to update the namespace to something appropriate for your Web site.
With a way to store the data, we now need to write the custom SOAP attribute. (Chapter 4, “Using Attributes to Shape the WSDL and XML,” covered the particulars of custom SOAP attributes.) This particular attribute will allow a user to audit any individual Web Method. The first class we need to implement inherits from SoapExtensionAttribute and is named AuditAttribute. This class, shown in Listing 5.5, allows the user of the class to set custom data through the otherData property.
Listing 5.5. The AuditAttribute Class
Imports System.Web.Services
Imports System.Web.Services.Protocols
Namespace com.scottseely
<AttributeUsage(AttributeTargets.Method)> _
Public Class AuditAttribute
Inherits SoapExtensionAttribute
' Stores the priority for the class
Private m_priority As Integer
Private m_otherData As String = ""
' Returns the type that inherits from
' SoapExtension
Public Overrides ReadOnly Property ExtensionType() As Type
Get
Return GetType(AuditExtension)
End Get
End Property
' Stores the Priority as set in the config file
' and returns that value on demand.
Public Overrides Property Priority() As Integer
Get
Return m_priority
End Get
Set(ByVal Value As Integer)
m_priority = Value
End Set
End Property
' Store the random data as requested by the
' user of the attribute.
Public Property otherData() As String
Get
Return m_otherData
End Get
Set(ByVal Value As String)
m_otherData = Value
End Set
End Property
End Class
End Namespace
|
Now comes the part that does the work of auditing the Web Method—AuditExtension. It derives from SoapExtension and does most of the work in the ProcessMessage override. This class uses the AuditEntry class to mark various events in the call of the Web Method as well as store information discovered about the method being called. The start time of the call is noted in the BeforeDeserialize stage before the Web Method itself gets interpreted. After interpreting the message but before calling the method (the AfterDeserialize stage), the attribute pulls out the method name and stores that. Then, after the method has executed and the response has been created, the AfterSerialize stage checks for any faults. If a fault did occur, the cause of the fault is noted in the otherData member of the AuditEntry instance and the method checks to see if the client or server is responsible for the fault. Regardless of success or failure, the processing for the stage finishes by noting the end time. The AuditEntry instance then saves itself to the database and auditing for the method is complete. Listing 5.6 shows the code for the AuditExtension class.
Listing 5.6. The AuditExtension Class
Imports System.Web.Services
Imports System
Imports System.Web.Services.Protocols
Imports System.IO
Imports System.Xml
Namespace com.scottseely
Public Class AuditExtension
Inherits SoapExtension
Private m_auditEntry As AuditEntry
' We don't manipulate the stream.
' Just throw it back at the caller.
Public Overrides Function ChainStream( _
ByVal stream As Stream) As Stream
Return stream
End Function
' Both GetInitializer overrides are present but do nothing.
Public Overloads Overrides Function GetInitializer( _
ByVal methodInfo As LogicalMethodInfo, _
ByVal attribute As SoapExtensionAttribute) As Object
Dim theAttr As AuditAttribute = attribute
Return theAttr.otherData
End Function
Public Overloads Overrides Function GetInitializer( _
ByVal WebServiceType As Type) As Object
' No initializer used. By default, this returns Nothing
m_auditEntry.otherData = "What the heck2" 'theAttr.otherData
Return "No special data set"
End Function
' Implemented because it has to be but does nothing.
Public Overrides Sub Initialize(ByVal initializer As Object)
m_auditEntry.otherData = CStr(initializer)
End Sub
' Handle any chaining of the message between old and new.
' Besides that, manipulate the stream as needed
Public Overrides Sub ProcessMessage(ByVal message As SoapMessage)
Select Case message.Stage
Case SoapMessageStage.BeforeSerialize
Case SoapMessageStage.AfterSerialize
m_auditEntry.endTime = DateTime.Now
If (message.Exception Is Nothing) Then
m_auditEntry.callResult = CallResult.Success
Else
m_auditEntry.otherData = _
message.Exception.ToString()
If (message.Exception.Code Is _
SoapException.ClientFaultCode) Then
m_auditEntry.callResult = _
CallResult.ClientFailure
Else
m_auditEntry.callResult = _
CallResult.ServerFailure
End If
End If
m_auditEntry.Save()
Case SoapMessageStage.BeforeDeserialize
m_auditEntry.startTime = DateTime.Now
Case SoapMessageStage.AfterDeserialize
m_auditEntry.methodName = _
message.MethodInfo.Name
Case Else
Throw New Exception("invalid stage")
End Select
End Sub
Public Sub New()
m_auditEntry = New AuditEntry()
End Sub
End Class
End Namespace
|
To use the attribute, just apply to a Web Method and you are ready to go. Listing 5.7 shows a couple of Web Methods that use the attribute to implement logging with just one line of code.
Listing 5.7. Example of Using the Custom Attribute
<WebMethod(), _
Audit.com.scottseely.Audit(otherData:="This is a test")> _
Public Function HelloWorld() As String
Return "Hello World!"
End Function
<WebMethod(), _
Audit.com.scottseely.Audit(otherData:="Another method")> _
Public Function AnotherMethod() As String
Return "Yet another method"
End Function
|
The Web Service and a test application are included in the sample files on the companion Web site for you to see how everything works. The Web Service is named AuditTestService and the console application is named AuditTestConsole. Auditing is an often overlooked part of developing a Web Service. I hope the sample code here will help you add this basic functionality to your own Web Services.