Part 2: Enhanced T-SQL Error Handling With Extended Events

2016-09-18 0 Comments

TSQL Error Handling With Extended Events

In the last post, we explored a couple of examples of using Extended Events to enhance T-SQL error handling. There was some potential there. But a hard-coded SPID was necessary: we couldn't use the code examples for anything automated. It was cumbersome, too. Let's change that, shall we?

To make the code easier to work with, I moved most of it into three stored procs: one each to create an XEvent session, get the XEvent session data, and drop the XEvent session. There's also a table type. This will negate the need to declare a temp table over and over. The four objects can be created in any database you choose. I opted to create them in [tempdb]. The code for each is below in the four tabs. 

USE ;
GO

IF NOT EXISTS (
    SELECT *
    FROM INFORMATION_SCHEMA.ROUTINES r
    WHERE r.ROUTINE_SCHEMA = 'dbo'
    AND r.ROUTINE_NAME = 'CreateXESession_ErrorReported'
)
BEGIN
    EXEC('CREATE PROC dbo.CreateXESession_ErrorReported AS PRINT CURRENT_TIMESTAMP;');
END;
GO

ALTER PROC dbo.CreateXESession_ErrorReported
/*
 Purpose: 
 Creates and starts an Extended Events Session to monitor errors (if any) that occur.
 The session is filtered by the current SPID. 
 
 Inputs: none.

 History:
 09/05/2016 DMason Created
*/
AS
BEGIN
    DECLARE @XESessionName SYSNAME =
        'Error Handling Session(SPID ' + CAST(@@SPID AS VARCHAR) + ')';

    IF EXISTS(
        SELECT *
        FROM master.sys.server_event_sessions s
        WHERE s.name = @XESessionName
    )
    BEGIN
        DECLARE @ErrMsg NVARCHAR(MAX) = 'Session ' + @XESessionName + ' already exists.';
        RAISERROR(@ErrMsg, 16, 1);
        RETURN;
    END

    --Include SPID within session name for isolation.
    DECLARE @TSql NVARCHAR(MAX) = 'CREATE EVENT SESSION [' + @XESessionName + '] 
ON SERVER 
ADD EVENT sqlserver.error_reported
(
    ACTION(
        sqlserver.session_id,
        sqlserver.sql_text
    )
    WHERE [package0].[not_equal_unicode_string]([message],N'''''''''''') 
    AND [severity]>(10) 
    AND [sqlserver].[session_id]=(' + CAST(@@SPID AS VARCHAR) + ')
) 
ADD TARGET package0.ring_buffer
WITH (
    --NO_EVENT_LOSS fails on SQL 2014 SP2
    --ALLOW_SINGLE_EVENT_LOSS
    EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,

    MAX_MEMORY=4096 KB,
    MAX_DISPATCH_LATENCY=1 SECONDS,
    MAX_EVENT_SIZE=0 KB,
    MEMORY_PARTITION_MODE=NONE,
    TRACK_CAUSALITY=ON,
    STARTUP_STATE=OFF
);'
    --PRINT @TSql;
    EXEC(@TSql);

    SET @TSql = 'ALTER EVENT SESSION [' + @XESessionName + '] ON SERVER STATE=START;';
    EXEC(@TSql);
END
GO

USE tempdb;
GO

IF NOT EXISTS (
    SELECT *
    FROM INFORMATION_SCHEMA.ROUTINES r
    WHERE r.ROUTINE_SCHEMA = 'dbo'
    AND r.ROUTINE_NAME = 'GetXESessionData_ErrorReported'
)
BEGIN
    EXEC('CREATE PROC dbo.GetXESessionData_ErrorReported AS PRINT CURRENT_TIMESTAMP;');
END;
GO

ALTER PROC dbo.GetXESessionData_ErrorReported
/*
 Purpose: 
 Returns Extended Events Session data.
 
 Inputs: none.

 History:
 09/15/2016 DMason Created
*/
AS
BEGIN
    --SPID included within session name for isolation.
    DECLARE @XESessionName SYSNAME =
        'Error Handling Session(SPID ' + CAST(@@SPID AS VARCHAR) + ')';

    IF NOT EXISTS(
        SELECT *
        FROM master.sys.server_event_sessions s
        WHERE s.name = @XESessionName
    )
    BEGIN
        DECLARE @ErrMsg NVARCHAR(MAX) = 'Session ' + @XESessionName + ' does not exist.';
        RAISERROR(@ErrMsg, 16, 1);
        RETURN;
    END

    DECLARE @XEData XML

    SELECT @XEData = CAST(xet.target_data AS XML)
    FROM sys.dm_xe_session_targets AS xet
    JOIN sys.dm_xe_sessions AS xe
        ON (xe.address = xet.event_session_address)
    WHERE xe.name = @XESessionName;

    /*
  Check value of "totalEventsProcessed" to ensure events have been 
  dispatched to event session target (ring_buffer).
  If no events have been processed, delay for a period > MAX_DISPATCH_LATENCY (in seconds).
 */
    IF @XEData.value('(/RingBufferTarget/@totalEventsProcessed)[1]', 'INT') = 0
    BEGIN
        WAITFOR DELAY '00:00:02';

        SELECT @XEData = CAST(xet.target_data AS XML)
        FROM sys.dm_xe_session_targets AS xet
        JOIN sys.dm_xe_sessions AS xe
            ON (xe.address = xet.event_session_address)
        WHERE xe.name = @XESessionName;
    END

    /*
  SELECT signature must match the [dbo].[ErrorReported] table type:
 */
    SELECT 
        x.c.value(N'(action[@name="session_id"]/value)[1]', N'SMALLINT') AS SessionId,
        x.c.value(N'(@name)[1]', N'NVARCHAR(MAX)') AS EventName,
        x.c.value(N'(@timestamp)[1]', N'datetime') AS EventTime,
        x.c.value(N'(data[@name="error_number"]/value)[1]', N'INT') AS ErrorNumber,
        x.c.value(N'(data[@name="severity"]/value)[1]', N'INT') AS Severity,
        x.c.value(N'(data[@name="state"]/value)[1]', N'INT') AS [State],
        x.c.value(N'(data[@name="user_defined"]/value)[1]', N'NVARCHAR(MAX)') AS UserDefined,
        x.c.value(N'(data[@name="category"]/text)[1]', N'NVARCHAR(MAX)') AS Category,
        x.c.value(N'(data[@name="destination"]/text)[1]', N'NVARCHAR(MAX)') AS Destination,
        x.c.value(N'(data[@name="is_intercepted"]/value)[1]', N'NVARCHAR(MAX)') AS IsIntercepted,
        x.c.value(N'(data[@name="message"]/value)[1]', N'NVARCHAR(MAX)') AS [Message],
        x.c.value(N'(action[@name="sql_text"]/value)[1]', N'NVARCHAR(MAX)') AS SqlText
    FROM @XEData.nodes('//RingBufferTarget/event') AS x(c)
END
GO

USE tempdb;
GO

IF NOT EXISTS (
    SELECT *
    FROM INFORMATION_SCHEMA.ROUTINES r
    WHERE r.ROUTINE_SCHEMA = 'dbo'
    AND r.ROUTINE_NAME = 'DropXESession_ErrorReported'
)
BEGIN
    EXEC('CREATE PROC dbo.DropXESession_ErrorReported AS PRINT CURRENT_TIMESTAMP;');
END;
GO

ALTER PROC dbo.DropXESession_ErrorReported
/*
 Purpose: 
 Stops and drops an Extended Events Session that monitor errors.
 
 Inputs: none.

 History:
 09/05/2016 DMason Created
*/
AS
BEGIN
    --SPID included within session name for isolation.
    DECLARE @XESessionName SYSNAME =
        'Error Handling Session(SPID ' + CAST(@@SPID AS VARCHAR) + ')';

    IF EXISTS(
        SELECT *
        FROM master.sys.server_event_sessions s
        WHERE s.name = @XESessionName
    )
    BEGIN
        DECLARE @TSql NVARCHAR(MAX) = 'ALTER EVENT SESSION [' + @XESessionName + '] ON SERVER STATE=STOP;';
        EXEC(@TSql);

        SET @TSql = 'DROP EVENT SESSION [' + @XESessionName + '] ON SERVER;';
        EXEC(@TSql);
    END
END
GO

USE tempdb;
GO

IF NOT EXISTS (
    SELECT *
    FROM sys.types
    WHERE name = 'ErrorReported'
    AND schema_id = SCHEMA_ID('dbo')
)
BEGIN
    CREATE TYPE dbo.ErrorReported AS TABLE (
        SessionId SMALLINT,
        EventName NVARCHAR(MAX),
        EventTime DATETIME,
        ErrorNumber INT,
        Severity INT,
        [State] NVARCHAR(MAX),
        UserDefined NVARCHAR(MAX),
        Category NVARCHAR(MAX),
        Destination NVARCHAR(MAX),
        IsIntercepted NVARCHAR(MAX),
        [Message] NVARCHAR(MAX),
        SqlText NVARCHAR(MAX)
    )
END
GO


Now that those objects are created, take a look at a few examples that use them below. It's pretty easy now, right? The first two examples are identical, save for the statement in the TRY block. In the third example, we have to check for the existence of session error data outside of the CATCH block, because DBCC CHECKDB errors don't pass control to the CATCH block. No matter--we can still "catch" them now. The output from SSMS is viewable at the bottom of each tab/script (images edited for viewability). 

USE tempdb;
GO

--Create an Extended Events Session for the current SPID.
EXEC dbo.CreateXESession_ErrorReported;

BEGIN TRY
    BACKUP DATABASE master
    TO DISK = 'master.diff.bak' WITH DIFFERENTIAL;
END TRY
BEGIN CATCH
    --Create a temp table (as a table type)...
    DECLARE @ErrData AS dbo.ErrorReported;
    
    --...insert session error data into it.
    INSERT INTO @ErrData 
    EXEC dbo.GetXESessionData_ErrorReported;

    SELECT * FROM @ErrData;
END CATCH

--Drop the Extended Events Session for the current SPID.
EXEC dbo.DropXESession_ErrorReported;
GO



TSQL Error Handling With Extended Events - Backup Database


USE tempdb;
GO

--Create an Extended Events Session for the current SPID.
EXEC dbo.CreateXESession_ErrorReported;

BEGIN TRY
    RESTORE DATABASE Foo
    FROM DISK = 'Foo.bak';
END TRY
BEGIN CATCH
    --Create a temp table (as a table type)...
    DECLARE @ErrData AS dbo.ErrorReported;
    
    --...insert session error data into it.
    INSERT INTO @ErrData 
    EXEC dbo.GetXESessionData_ErrorReported;

    SELECT * FROM @ErrData;
END CATCH

--Drop the Extended Events Session for the current SPID.
EXEC dbo.DropXESession_ErrorReported;
GO



TSQL Error Handling With Extended Events - Restore Database


USE tempdb;
GO

--Create an Extended Events Session for the current SPID.
EXEC dbo.CreateXESession_ErrorReported;

BEGIN TRY
    DBCC CHECKDB('CorruptionTest') 
    WITH NO_INFOMSGS;
END TRY
BEGIN CATCH
    PRINT 'Hello world...';
END CATCH

--Create a temp table (as a table type)...
DECLARE @ErrData AS dbo.ErrorReported;

--...insert session error data into it.
INSERT INTO @ErrData 
EXEC dbo.GetXESessionData_ErrorReported;

IF EXISTS (SELECT * FROM @ErrData)
BEGIN
    SELECT * FROM @ErrData;
END

--Drop the Extended Events Session for the current SPID.
EXEC dbo.DropXESession_ErrorReported;
GO


TSQL Error Handling With Extended Events - DBCC CHECKDB


Automation

Now let's make something useful. Here's a script that uses a cursor, iterates through a set of database names, and attempts a LOG backup of each database. If the t-log backup fails, we'll append to a string of error numbers and error messages. But instead of failing the batch, we'll move on to the next database name in the loop. At the conclusion of the loop, we check for errors, and if any occurred, an email alert is sent. In this particular example, the cursor was specifically created so that *all* of the LOG backup attempts would fail. In a more realistic scenario, most (if not all) of the LOG backups would succeed. If there was a single failure, the batch would continue, allowing the remaining database logs to get backed up. 

USE tempdb;
GO

EXEC dbo.CreateXESession_ErrorReported;

DECLARE @DBName SYSNAME;
DECLARE curDB CURSOR FAST_FORWARD READ_ONLY FOR
    --A transaction log backup will fail for all of these DB's
    SELECT DB_NAME(database_id)
    FROM sys.database_recovery_status 
    WHERE last_log_backup_lsn IS NULL
DECLARE @ErrOccurred BIT = 0;
DECLARE @ErrData AS dbo.ErrorReported;

--This will be the body of an HTML-formatted email message.
DECLARE @Body NVARCHAR(MAX) = '<table border="1">' +
    '<tr>' +
    '<th>Database Name</th>' +
    '<th>Error Number</th>' +
    '<th>Error Message</th>' +
    '</tr>';

OPEN curDB;
FETCH NEXT FROM curDB INTO @DBName;

WHILE @@FETCH_STATUS = 0
BEGIN
    DECLARE @Path VARCHAR(255) = @DBName + '.log.bak';

    BEGIN TRY
        BACKUP LOG @DBName
        TO DISK = @Path;
    END TRY
    BEGIN CATCH
        SET @ErrOccurred = 1;

        INSERT INTO @ErrData 
        EXEC dbo.GetXESessionData_ErrorReported;

        --Add "rows" to the HTML <table>.
        SELECT @Body = @Body + CHAR(13) + CHAR(10) + '<tr>' +
            '<td>' + @DbName + '</td>' +
            '<td>' + CAST(e.ErrorNumber AS VARCHAR) + '</td>' +
            '<td>' + e.[Message] + '</td>' +
            '</tr>'
        FROM @ErrData e

        --Drop & recreate the XEvent session to clear out the ring buffer target.
        EXEC dbo.DropXESession_ErrorReported;
        EXEC dbo.CreateXESession_ErrorReported;
        DELETE FROM @ErrData;
    END CATCH

    FETCH NEXT FROM curDB INTO @DBName;
END

CLOSE curDB
DEALLOCATE curDB
EXEC dbo.DropXESession_ErrorReported;

IF @ErrOccurred = 1
BEGIN
    DECLARE @Subject NVARCHAR(255) = @@SERVERNAME + ' -- Trx Log Backup Errors';
    SET @Body = @Body + '</table>'
    
    EXEC msdb.dbo.sp_send_dbmail
        @recipients = 'You@YourDomain.com', 
        @subject = @Subject,
        @body = @Body,
        @body_format = 'HTML'

    --Optional: RAISERROR()
END
GO

Lastly, here's a screen shot of our email alert. All of our errors and messages are accounted for:

SQL Server - TSQL Error Handling With Extended Events - Email Alert

UPDATE:
A humble and heartfelt thank you to SQL Server MVP Erland Sommarskog. In his epic series Error and Transaction Handling in SQL Server, Erland pays me a compliment for my efforts here in this post.

0 comments:

Subscribe to: Post Comments (Atom)