Last week I was trying to troubleshoot some activation stored procedures in Service Broker.  One nice thing about this framework is that it logs activation procedure errors in the SQL Server error log, since activation is not an interactive experience.  You will see error messages like this:

(And yes, I could have disabled activation and debugged manually, but since the errors were few and far between and depended upon user input, this was not trivial.  You can see this article for a tutorial on this, as well as some of the limitations on actively debugging a Service Broker queue.  There is also useful some information in this page from Books Online.) 

On the down side, loading these logs through SQL Server Management Studio is cumbersome, especially if your instance has been up for some time.  You have to wait for the entire set of log data to load, and only then can you filter to restrict the results to only include error messages like the above.  So I started thinking about a better way of reviewing the error logs without relying on the GUI within SSMS.

My first attempt, of course, was to load the error log files into a work table through BCP or BULK INSERT, then filter and query against it.  This was troublesome because (a) I had to dynamically determine the location of the log files for each instance, and (b) the most current log file cannot be accessed in this way because it is currently in use by SQL Server.  So, I could get at it this way by shutting down SQL Server and accessing the log files from another instance (or copying the most current log file and then restarting SQL Server), but this is not exactly ideal.

My next attempt was to use xp_cmdshell 'type <path>\ERRORLOG[.x]' with the same intent.  This got around the "in use" problem, but it still had the issue that I needed to determine <path> on each instance; also, it introduced a new problem: the output is truncated at 255 characters, which made troubleshooting very difficult indeed, since I could not see a single complete error message.

So my third and final attempt was to use the undocumented stored procedures sp_enumerrorlogs and sp_readerrorlog.  Two things you should know about these procedures: (1) they are undocumented, and therefore unsupported; and (2) the behavior can change between SQL Server releases.  In fact, the output of sp_readerrorlog DID change between SQL Server 2000 and SQL Server 2005.  When I first tried this procedure in SQL Server 2005, I was quite puzzled, and am amazed to still find that most references on the web still show its former behavior.  However, I feel fairly confident using both procedures in SQL Server 2005 and SQL Server 2008 instances, since that is what SSMS uses to generate the log viewer within the GUI.  Something to keep in mind, though, when there is a new release of Management Studio in a few years.

I wrote a stored procedure that basically provides the same output as the SQL Server error log viewer, but allows me to filter on content and on date range.  On one of my more interesting systems I have 500+ databases, so another important thing I filter out of the output by default is database/log backup activity.  You can add your own filters to leave out information having to do with replication, or mirroring, or cluster failovers, etc.

One surprise was realizing that the LogDate is stored in UTC and not local time.  This is logical of course, but led to some finger-scratching when I was searching for errors that happened in the last 5 minutes.  It would be tricky to convert all log data to local time, especially if your log files straddle a daylight savings time boundary; so just remember that when passing datetime values into the stored procedure.  If you use your local time for boundaries, you might unknowingly leave out relevant events, or include irrelevant ones.  Anyway, here is the procedure:

USE [MyUtilityDatabase];
GO
IF OBJECT_ID('dbo.SearchSQLErrorLogs', 'P') IS NOT NULL
   DROP PROCEDURE dbo.SearchSQLErrorLogs;
GO
CREATE PROCEDURE dbo.SearchSQLErrorLogs
   @SearchString   NVARCHAR(255) = '',
   @StartDate      DATETIME      = NULL,
   @EndDate        DATETIME      = NULL,
   @IgnoreBackups  BIT           = 1,
   @CurrentLogOnly BIT           = 0
AS
BEGIN
   SET NOCOUNT ON;
   IF OBJECT_ID('tempdb..#Log', 'U') > 0
       DROP TABLE #Log;
 
   IF OBJECT_ID('tempdb..#Logs', 'U') > 0
       DROP TABLE #Logs;
 
   DECLARE
       @FirstLog   INT,
       @LastLog    INT,
       @CurrentLog INT;
 
   IF @StartDate IS NULL
       SET @FirstLog = 6;
 
   IF @EndDate IS NULL
       SET @LastLog = 0;
 
   SELECT 
       @StartDate = COALESCE(@StartDate, '19000101'),
       @EndDate = COALESCE(@EndDate, GETUTCDATE()),
       @SearchString = '%' + COALESCE(@SearchString, '') + '%';
 
   IF @CurrentLogOnly = 0 OR COALESCE(@FirstLog, @LastLog) IS NULL
   BEGIN
       CREATE TABLE #logs
       (
           ArchiveNo TINYINT,
           dt DATETIME,
           sz BIGINT
       );
 
       INSERT #logs
           EXEC [master].dbo.sp_enumerrorlogs
               @p1 = 1;
 
       SELECT
           @FirstLog = MAX(ArchiveNo),
           @LastLog = MIN(ArchiveNo)
       FROM
       (
           SELECT 
               ArchiveNo,
               [Start] = COALESCE(
                   (
                       SELECT dt FROM #Logs
                       WHERE ArchiveNo = L.ArchiveNo + 1
                   ), '19000101'),
               [End] = dt
           FROM
               #Logs AS L
       ) AS x
       WHERE
           [Start] BETWEEN @StartDate AND @EndDate
           OR [End] BETWEEN @StartDate AND @EndDate;
 
       IF OBJECT_ID('tempdb..#Logs', 'U') > 0
           DROP TABLE #Logs;
   END
 
   IF @CurrentLogOnly = 1
   BEGIN
       SELECT @FirstLog = 0, @LastLog = 0;
   END
 
   CREATE TABLE #Log 
   (
       LogDate     DATETIME,
       ProcessInfo VARCHAR(64),
       MessageText NVARCHAR(MAX)
   );
   CREATE CLUSTERED INDEX d ON #Log(LogDate);
 
   SELECT @CurrentLog = @FirstLog;
 
   WHILE @CurrentLog >= @LastLog
   BEGIN
       INSERT #Log
           EXEC [master].dbo.sp_readerrorlog
               @p1 = @CurrentLog;
 
       SET @CurrentLog = @CurrentLog - 1;
   END
 
   IF @IgnoreBackups = 1
   BEGIN
       DELETE #Log
           WHERE ProcessInfo = 'Backup'
           AND (
               MessageText LIKE 'Database backed up%'
               OR MessageText LIKE 'Log backed up%'
           );
   END
 
   SELECT LogDate, MessageText
       FROM #Log
       WHERE LogDate BETWEEN @StartDate AND @EndDate
       AND MessageText LIKE @SearchString
       ORDER BY LogDate;
 
   IF OBJECT_ID('tempdb..#Log', 'U') > 0
       DROP TABLE #Log;
END
GO

And here is the syntax I used to discover all service broker activation errors over the past few days:

DECLARE @start SMALLDATETIME = DATEADD(DAY, -3, DATEDIFF(DAY, 0, CURRENT_TIMESTAMP));
 
EXEC [MyUtilityDatabase].dbo.SearchSQLErrorLogs
   @StartDate = @start,
   @SearchString = 'activated proc%myActivationProc%on queue%myQueueName';

Hope you find the procedure useful.  I'm all ears, of course, if you spot problems or have enhancement suggestions.