CODEWITHSUNDEEP
sql-serverstored-proceduresdbccextended-events
Evaldas Buinauskas
Evaldas Buinauskas

Reputation: 14077

SQL Server logging failed queries

I'm trying to implement a system-wide logging, which would log all failed Stored Procedure executions in our dabatase and I'm looking at Extended Events.

I've done some research and it seems quite easy to capture failed statements using following code:

--Create an extended event session
CREATE EVENT SESSION what_queries_are_failing ON SERVER
ADD EVENT sqlserver.error_reported (
    ACTION (sqlserver.sql_text
        , sqlserver.tsql_stack
        , sqlserver.database_id
        , sqlserver.username
        )
    WHERE ([severity] > 10)
    )
ADD TARGET package0.asynchronous_file_target (
    SET filename = 'C:\XEventSessions\what_queries_are_failing.xel'
    , metadatafile = 'C:\XEventSessions\what_queries_are_failing.xem'
    , max_file_size = 5
    , max_rollover_files = 5
    )
    WITH (MAX_DISPATCH_LATENCY = 5 SECONDS)
GO

-- Start the session
ALTER EVENT SESSION what_queries_are_failing ON SERVER STATE = START
GO

;WITH events_cte
AS (
    SELECT DATEADD(mi, DATEDIFF(mi, GETUTCDATE(), CURRENT_TIMESTAMP), xevents.event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [err_timestamp]
        , xevents.event_data.value('(event/data[@name="severity"]/value)[1]', 'bigint') AS [err_severity]
        , xevents.event_data.value('(event/data[@name="error_number"]/value)[1]', 'bigint') AS [err_number]
        , xevents.event_data.value('(event/data[@name="message"]/value)[1]', 'nvarchar(512)') AS [err_message]
        , xevents.event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)') AS [sql_text]
        , xevents.event_data
    FROM sys.fn_xe_file_target_read_file('S:\XEventSessions\what_queries_are_failing*.xel', 'S:\XEventSessions\what_queries_are_failing*.xem', NULL, NULL)
    CROSS APPLY (
        SELECT CAST(event_data AS XML) AS event_data
        ) AS xevents
    )
SELECT *
FROM events_cte
ORDER BY err_timestamp;

However I'd like to immediately store failed statement into a table, let's call it Logs.Errors but I couldn't find a way to do it and the upper method would have to work as a scheduled job.

Right now, our procedures look like that:

CREATE PROCEDURE [dbo].[MyProcedure]
AS
BEGIN
    SET NOCOUNT ON;
    BEGIN TRY
        SELECT 1;
    END TRY
    BEGIN CATCH
        EXECUTE Logs.PrintError;
        EXECUTE Logs.LogError;
    END CATCH
END

Where Logs.LogError procedure is making use of DBCC INPUTBUFFER(); but it doesn't capture parameters, just the exact procedure that was executed. That's all I can get from it:

+----------------------------+-----------+-----------+------------------------------+
|        ErrorMessage        | EventType | Parameter |          Statement           |
+----------------------------+-----------+-----------+------------------------------+
| Incorrect syntax near '.'. | RPC Event |         0 | DbName.dbo.FailedProcedure;1 |
+----------------------------+-----------+-----------+------------------------------+

I'm looking for a way to either make DBCC INPUTBUFFER() work by forcing it to capture whole statement or XE to insert records straight into some table, if that's possible.

Any questions - let me know.

Upvotes: 4

Views: 2441

Answers (1)

Dave Mason
Dave Mason

Reputation: 4936

I've found that XEvents are great for monitoring events as they happen. However, they don't provide a mechanism to "handle" observed events. To fill that gap, I've used Event Notifications. I often describe them as asynchronous DDL triggers. I'll let you decide if that tl;dr definition is accurate or not.

If you want to give event notifications a try, here is a script that you can start with (sorry, it's really long). Let me know if you have any questions/issues. I'll try to reply as best as I can.

--Create these objects within a database that has service broker enabled.
USE DbaData
GO

--Drop objects first before trying to create them (in specific sequence).
IF EXISTS (
    SELECT *
    FROM sys.services
    WHERE name = 'svcUserErrorReportedNotification'
)
    DROP SERVICE svcUserErrorReportedNotification;
GO

IF EXISTS (
    SELECT *
    FROM sys.service_queues
    WHERE name = 'queUserErrorReportedNotification'
)
    DROP QUEUE queUserErrorReportedNotification;
GO

IF EXISTS (
    SELECT * 
    FROM sys.server_event_notifications 
    WHERE name = 'enUserErrorReportedEvents'
)
    DROP EVENT NOTIFICATION enUserErrorReportedEvents
    ON SERVER
GO

--Create a queue just for user error events.
CREATE QUEUE queUserErrorReportedNotification
GO

--Create a service just for user error events.
CREATE SERVICE svcUserErrorReportedNotification
ON QUEUE queUserErrorReportedNotification ([http://schemas.microsoft.com/SQL/Notifications/PostEventNotification])
GO

-- Create the event notification for user error events on the service.
CREATE EVENT NOTIFICATION enUserErrorReportedEvents
ON SERVER
WITH FAN_IN
FOR USER_ERROR_MESSAGE
TO SERVICE 'svcUserErrorReportedNotification', 'current database';
GO

IF EXISTS (
    SELECT *
    FROM INFORMATION_SCHEMA.ROUTINES r
    WHERE r.ROUTINE_SCHEMA = 'dbo' AND r.ROUTINE_NAME = 'ReceiveUserErrorReportedEvent'
)
    DROP PROCEDURE dbo.ReceiveUserErrorReportedEvent 
GO

CREATE PROCEDURE dbo.ReceiveUserErrorReportedEvent
/*****************************************************************************
* Name     : dbo.ReceiveUserErrorReportedEvent
* Purpose  : Runs when there is a USER_ERROR_MESSAGE event.
* Inputs   : None
* Outputs  : None
* Returns  : Nothing
******************************************************************************
* Change History
*   11/28/2016  DMason  Created
******************************************************************************/
AS
BEGIN
    SET NOCOUNT ON
    DECLARE @MsgBody XML

    WHILE (1 = 1)
    BEGIN
        BEGIN TRANSACTION

        -- Receive the next available message FROM the queue
        WAITFOR (
            RECEIVE TOP(1) -- just handle one message at a time
                @MsgBody = CAST(message_body AS XML)
                FROM queUserErrorReportedNotification
        ), TIMEOUT 1000  -- if the queue is empty for one second, give UPDATE and go away
        -- If we didn't get anything, bail out
        IF (@@ROWCOUNT = 0)
        BEGIN
            ROLLBACK TRANSACTION
            BREAK
        END 
        ELSE
        BEGIN
            --Grab some relevant items from the message body XML (it is EVENTDATA(), btw)
            DECLARE @Login SYSNAME;
            DECLARE @ErrMsgText VARCHAR(MAX);
            DECLARE @ApplicationName VARCHAR(MAX);
            DECLARE @Severity INT;
            DECLARE @ErrorNumber INT;
            DECLARE @DBName SYSNAME;

            SET @Login = @MsgBody.value('(/EVENT_INSTANCE/LoginName)[1]', 'VARCHAR(128)' );
            SET @ErrMsgText = @MsgBody.value('(/EVENT_INSTANCE/TextData)[1]', 'VARCHAR(MAX)' );
            SET @ApplicationName = @MsgBody.value('(/EVENT_INSTANCE/ApplicationName)[1]', 'VARCHAR(MAX)' );
            SET @Severity = @MsgBody.value('(/EVENT_INSTANCE/Severity)[1]', 'INT' );
            SET @ErrorNumber = @MsgBody.value('(/EVENT_INSTANCE/Error)[1]', 'INT' );
            SET @DBName = @MsgBody.value('(/EVENT_INSTANCE/DatabaseName)[1]', 'VARCHAR(128)' );

            --Do stuff here.
            --Log to a table, etc.

            /*
                Commit the transaction.  At any point before this, we 
                could roll back -- the received message would be back 
                on the queue AND the response wouldn't be sent.
            */
            COMMIT TRANSACTION
        END
    END
END
GO

ALTER QUEUE dbo.queUserErrorReportedNotification 
WITH 
STATUS = ON, 
ACTIVATION ( 
    PROCEDURE_NAME = dbo.ReceiveUserErrorReportedEvent, 
    STATUS = ON, 
    MAX_QUEUE_READERS = 1, 
    EXECUTE AS OWNER) 
GO

Upvotes: 3

Related Questions