A SQLCLR Stored Procedure that Writes to a Trace File

Download the Code for this issue here:

I’m always looking for better tools for debugging, tracing and logging.  You might recall the series of tracing tools that I’ve implementing in T-SQL and that were featured in issues #1 through #7 of this newsletter.  The simple stored procedure in this issue use capabilities of the CLR that improve on the original by writing the result to a file instead of a table.

Before we discuss the tracing stored procedure a few words about presentations, SQL Server 2005, etc. 

For starters, as of this issue, I’m working with the production release of SQL Server 2005!  That’s right, it shipped on Thursday October 27^th to MSDN subscribers.  After hours of downloading and a few reinstalls of Visual Studio 2005, I’m using the production bits.  Other versions should be available to everyone on November 7th or shortly thereafter.

If you’re in New England, you might want to stop by at one of two presentations that I’m giving.  Next Thursday, November 10th, I’ll be speaking to the New England SQL Server User Group about an application that I wrote for a recent client.  Do you ever execute ad hoc SQL against a production database?  I’m sure that lots of us do.  In the current regulatory environment, that is with HIPPA, SOX, Basel II, etc, auditors don’t like the idea.  The application that I wrote replaces SQL Query Analyzer and allows T-SQL and grid based updates to a production database but records every action.  There’s a lot of fun SQL involved including SQLXML, dynamically created stored procedures and more.  If you’re around, I’d love to see you there.

On December 1st, I’ll be doing the Visual Studio 2005 Launch event developer presentation for the New England Visual Basic Professionals at the Microsoft office in Waltham.  Now on to the issue content.

The advantage of writing to a file or other source that is external to SQL Server is that transaction rollbacks don’t affect messages stored in external files the way that they do messages stored in tables.  For that reason alone, I’m going to be supplementing usp_AppSession_Trace from Issue #3 with the stored procedure you’ll see below.

I started by using Visual Studio 2005 to create a new Visual Basic Database Project, which I named SQLClrExternal.  I’m naming it with the suffix External because this project is going to access resources outside of SQL Server and it’s going to need the “Permission Level” property of External.  I set this in the project properties.  When Visual Studio 2005 deploys the project to SQL Server 2005 it will specify External_Access as it creates the assembly.

SQLCLR assemblies must be created with one of three permission levels:

• Safe

• External (EXTERNAL_ACCESS)

• UnSafe

As you might surmise, Safe code is the most restrictive group and code in Safe assemblies can not access external files, the registry, web services, or other external resources. 

External assemblies may do anything a Safe assembly may do and may also access external resources.  That’s what this issue’s example does when it uses the Windows file system.

Unsafe assemblies use any CLR class and even used unmanaged code.  Unmanaged code means code from the Windows 32 environment, even if it was created with Visual Studio.  While using unsafe assemblies is something to be avoided, you should note that it’s no more unsafe than using an external stored procedure or a COM object with the sp_OA_* external stored procedures.

SQLCLR assemblies have an owner and the ownership of the assembly effects permissions.  In the short term, I’m going to use the defaults and create my assemblies to be owned by dbo.  That way they’ll execute in the security context of the account that SQL Server is running as.  On my development machine, that’s me.  In a production environment it is usually a service account.  However, if the account is a local account, without network privileges, SQLCLR code will be limited to the permissions of that account.

So let’s start our coding.  I start by adding a new stored procedure to the project and giving it the name usp_AppSession_TraceCLR.vb.  Here’s the project as Visual Studio creates it:

Imports System
Imports System.Data
Imports System.Data.SqlClient
Imports System.Data.SqlTypes
Imports Microsoft.SqlServer.Server

Partial Public Class StoredProcedures

    <Microsoft.SqlServer.Server.SqlProcedure()> _
    Public Shared Sub  usp_AppSession_TraceCLR ()
        ' Add your code here
    End Sub
End Class 

The attribute on the subroutine tells Visual Studio and SQL Server that this procedure is intended as a stored procedure.  There are other attributes for other types of SQLCLR code.

As the comment says, it’s time to “Add your code here”.  Well, actually it’s time to add the parameters first.  I’ll add a set of parameters that are similar to the parameters of usp_AppSession_Trace.  The difference is the first parameter.  Usp_AppSession_Trace uses it to return the ID of the trace record added by the procedure.  Usp_AppSession_TraceCLR uses the first parameter for the file name of the trace.

Since usp_AppSession_TraceCLR writes to a file it’s going to need that file name.  It’s also going to need a directory.  We could just let the caller specify the directory as part of the call.  We could even use a hard coded directory.  But that wouldn’t be very general purpose.  So I selected a two pronged strategy.  The procedure looks first for an environment variable named AppSession, which can contain the path of the a directory for trace files.. If it doesn’t find a path there, it gets the path of the temporary directory. It then uses the function TextSave to write to the file.  Here’s the completed method:

Option Strict On

Imports System
Imports System.Data
Imports System.Data.SqlClient
Imports System.Data.SqlTypes
Imports Microsoft.SqlServer.Server
Imports System.Text

Partial Public Class StoredProcedures

    <Microsoft.SqlServer.Server.SqlProcedure()> _
    Public Shared Sub usp_AppSession_TraceCLR( _
                ByVal TraceFileName As SqlString, _
                ByVal SessionID As SqlInt32, _
                ByVal RunningTraceLevel As SqlInt16, _
                ByVal MessageTraceLevel As SqlInt16, _
                ByVal Msg As SqlString, _
                ByVal TraceSource As String, _
                ByVal TraceCategory As String)

        Dim TraceLine As String
        Dim TraceFileFullPath As String

        TraceLine = String.Format("{0:yyyy-MM-dd hh:mm:ss.fff}-{1:N0}-{2}-{3}-{4}{5}", _
                                DateTime.Now, SessionID, TraceSource, TraceCategory, Msg, _
                                ControlChars.NewLine)

        ' Only do anything if the Running trace level is >= the level of the message
        If CShort(Math.Abs(CInt(RunningTraceLevel))) >= MessageTraceLevel Then

            If RunningTraceLevel < 0 Then

                TraceFileFullPath = System.Environment.GetEnvironmentVariabl
                                                          ("AppSessionTraceDir")
                If TraceFileFullPath Is Nothing OrElse TraceFileFullPath.Length = 0 Then
                    TraceFileFullPath = System.IO.Path.GetTempPath
                End If
                TraceFileFullPath &= TraceFileName.ToString

                System.IO.File.AppendAllText(TraceFileFullPath, TraceLine)
            ElseIf RunningTraceLevel > 0 Then
                SqlContext.Pipe.Send(TraceLine)
            End If
        End If
    End Sub

End Class

The business of the function is done either by the AppendAllText method, which appends the line to a file, or by the SqlContext.pipe.Send method.  SQLContext is a class of shared methods for communicating between the CLR code and the database engine.  In this case the Pipe.Send method writes a message to the SQL output.  It’s just like the T-SQL PRINT statement.

When Visual Studio deploys the project it creates a T-SQL stored procedure with this statement:

CREATE PROCEDURE [dbo].[usp_AppSession_TraceCLR]
        @TraceFileName [nvarchar](4000),
        @SessionID [int],
        @RunningTraceLevel [smallint],
        @MessageTraceLevel [smallint],
        @Msg [nvarchar](4000),
        Source [nvarchar](4000),       
        @TraceCategory [nvarchar](4000)
WITH EXECUTE AS CALLER
AS
EXTERNAL NAME [SQLClrExternal].[SQLClrExternal.StoredProcedures].
                          [usp_AppSession_TraceCLR]

The EXTERNAL NAME clause binds the stored procedure definition to the correct method in the assembly created for the project.  That’s how the SQL engine finds the correct code instead of having a T-SQL procedure body to execute.

To execute this stored procedure we need a T-SQL exec statement.  For easy debugging, the statement goes into the Test.sql file that Visual Studio added to the project when it was created.  If you wish to use a different test script file you can add the file to the project and then make it the context menu “Set as the default debugging script”.  Here’s the first exec statement:

-- This first message goes to the SQL message output stream.
exec dbo.usp_AppSession_TraceCLR 'myCLRLog.txt', 0,5, 3,
        'Now that''s what I call a message.', 'Test.sql', 'TestMsg'

So I pressed the debug arrow and hoped for the best.  The first problem showed up right away in the form of this statement:

Error 1     CREATE ASSEMBLY for assembly 'SQLClrExternal' failed because assembly 'SQLClrExternal' is not authorized for PERMISSION_SET = EXTERNAL_ACCESS.  The assembly is authorized when either of the following is true: the database owner (DBO) has EXTERNAL ACCESS ASSEMBLY permission and the database has the TRUSTWORTHY database property on; or the assembly is signed with a certificate or an asymmetric key that has a corresponding login with EXTERNAL ACCESS ASSEMBLY permission. SQLClrExternal

SQL Server 2005 doesn’t automatically trust code.  That includes code that is included in a database that is attached from some other location.  To get around this one, I decided on setting the TRUSTWORTHY property of the database with this statement:

ALTER DATABASE SQLCLR1 SET TRUSTWORTHY ON

So I tried again and got this message:

Execution of user code in the .NET Framework is disabled. Enable "clr enabled" configuration option.

Oh yea. The CLR is disabled by default and you have to enable it.  You’ll find the script on this tip page: http://www.novicksoftware.com/TipsAndTricks/tip-sql-server-2005-enable-clr-programming.htm

So I tried again and the debugger stopped at my first breakpoint on the exec statement in the Test.sql file.  That’s a T-SQL statement.  Pressing F11, and waiting about 20 seconds brought me into the Sub statement in the usp_AppSession_TraceCLR.vb file.  Fantastic!  T-SQL to CLR debugging works like a charm.

Stepping with F10 takes you through the statements of the function and the usual debugger features are available.  Or are they?

At this point I couldn’t help but try to see if “Edit and Continue” worked when debugging a SQLCLR routine.  Edit and Continue is a debugging feature that allows the programmer to change the code during debugging and continue the debugging session with the new code in effect.  The feature was a mainstay of Visual Basic versions 6 and below.  It was omitted from Visual Studio 2002 and 2003.  It’s back in Visual Studio 2005 in both VB.Net and C#.  Unfortunately it’s not available when debugging SQLCLR routines.  When I tried to change my code the editor displayed a message on the lower status bar saying:

Cannot currently modify this text in the editor. It is read-only.

Since the RunningTraceLevel is positive in this first call, the code stepped to the SQLContext.Pipe.Send method call.  This sent the message to the SQL output stream, which is displayed in Visual Studio’s Debug output window.  Here’s the output:

2005-11-03 12:48:28.640-0-Test.sql-TestMsg-Now that's what I call a message.

The second exec statement in the Test.SQL file has a negative value for RunningTraceLevel and the output of the statement is sent to the file. Here’s the exec statement:

-- This next messsage goes to the file.
exec dbo.usp_AppSession_TraceCLR 'myCLRLog.txt', 0,-5, 3,
       'Now that''s what I call a message.', 'Test.sql', 'TestMsg'

Since there’s no environment variable for “AppSessionTrace”, the code picked up the temp directory as and it was combined with the filename and the message was written to the file myCLRLog.txt in my temp directory.

So now we have an easy way to write log messages to a text file.  The file is opened and closed on each call, so we can be assured that the statement is flushed to the disk during the call. 

A file is just one of the choices that are available.  We might also use other external resources such as the Event Log, a Web Service, an MSMQ message queue, or others that I can't even think of.  Another possibility is that the message is written to a database on a separate connection, keeping it out of the current transaction.

Download the Code for this issue here: